Production Debugging: Test Hypotheses, Not Guesses

A purchase-order request for a one-year range is slow. The README frames the incident as a 504 Gateway Timeout. Is the handler serializing too much JSON? Is the service doing expensive work? Is the repository slow?

Lab 11 turns those guesses into an investigation. Its most useful lesson is not simply “measure every layer.” It is understand what each measurement includes before using it as evidence.

Debugging is testing hypotheses, not guessing causes.

The scenario and the implementation are different things

The lab contains README.md, main.go, and main_test.go. The implementation is an in-process Go simulation: a handler calls a service, which calls a repository. Tests invoke HandleGetOrders directly.

There is no HTTP server, load balancer, database query, or JSON serialization in these files. The 504 is the motivating scenario, not an HTTP response generated by the tests. Missing indexes and inefficient queries are analogies in the README, not demonstrated database findings.

Here is the complete slow repository method from main.go, formatted for readability:

func (r *SlowRepository) FetchOrders(
    ctx context.Context, rangeType string,
) ([]PurchaseOrder, error) {
    if rangeType == "1y" {
        time.Sleep(4 * time.Second)
    } else {
        time.Sleep(10 * time.Millisecond)
    }
    return []PurchaseOrder{{ID: "po-1", Amount: 100}}, nil
}

The one-year input selects a four-second sleep. Every other input selects a ten-millisecond sleep. Both paths return one order, not different-sized datasets. There is no date filtering or range validation. This matters: the experiment models latency, not the cost of retrieving a larger result set.

Reproduce one specific condition

TestReproduceBug wires SlowRepository into the service and calls the handler with "1y". It fails when TotalDuration < 4*time.Second. Precisely, the assertion accepts a duration of at least four seconds; the failure message's > 4s is slightly looser wording.

From the repository root, the README's workflow is:

cd labs/11-debugging-production
go test -v -run TestReproduceBug
go test -v -run TestCollectEvidence
go test -v -run TestVerifyFix

The root go.mod specifies Go 1.25.0. Go is unavailable in the environment used to prepare this article, so I inspected these tests rather than running them. The timing arithmetic below is derived from source, not benchmark output or a claim that tests passed.

Give each hypothesis a falsifiable question

README hypothesis	What the evidence must distinguish
H1: handler / JSON work	Handler-local work versus time spent downstream; JSON is not implemented here.
H2: service business logic	Service-local work versus waiting inside the repository call.
H3: repository	Whether changing the repository while holding the other parts fixed removes the modeled delay.

A slow service measurement does not automatically support H2. A caller's timer can include its dependency. Similarly, a small preparation timer cannot establish that JSON serialization is fast when serialization never occurs.

Service time is inclusive

This is the complete Service.GetOrders method, with its signature wrapped:

func (s *Service) GetOrders(
    ctx context.Context, rangeType string,
) ([]PurchaseOrder, time.Duration, error) {
    start := time.Now()
    time.Sleep(10 * time.Millisecond)
    orders, err := s.repo.FetchOrders(ctx, rangeType)
    dur := time.Since(start)
    return orders, dur, err
}

The timer starts before the service's simulated work and stops after FetchOrders returns. ServiceDuration therefore includes repository time. With the slow repository, the configured sleep contribution is 10 ms + 4000 ms, not 10 ms alone.

The handler then derives repository time using this excerpt:

totalDur := time.Since(totalStart)
repoDur := svcDur - 10*time.Millisecond

That is a subtraction, not an independently measured repository span. Any excess time in service scheduling or other overhead can remain in the derived value. Calling the field RepositoryDuration does not change its measurement boundary.

Field	Actual meaning in the code
HandlerDuration	Handler preparation only, including a 5 ms sleep.
ServiceDuration	Inclusive service work plus the repository call.
RepositoryDuration	Service duration minus a fixed 10 ms.
TotalDuration	Elapsed time across the successful handler path.

Do not add handler, service, and repository durations together. Service already includes repository time, so that would double-count the repository. The general habit is to ask where every timer starts and stops before comparing its value with another timer.

The example log is not output from this implementation

The README shows service_duration=12ms alongside repository_duration=4200ms. That pairing is inconsistent with the current calculation: repository duration equals service duration minus 10 ms. It cannot be treated as actual output from this code.

The configured sleep budgets are:

Path	Sum of configured sleeps
Slow repository, 1y	5 + 10 + 4000 = 4015 ms
Slow repository, other input	5 + 10 + 10 = 25 ms
Fast repository, 1y	5 + 10 + 10 = 25 ms

These are source-derived sums, not measured runtimes. Scheduling and overhead affect real elapsed time. The README's claim that 1m takes less than 20 ms also conflicts with the 25 ms of configured sleeps in the current code.

TestCollectEvidence prints the duration fields but does not assert a bottleneck relationship. Its request_id=abc123 line is hardcoded; it is not a unique-ID generator or a tracing implementation. Printing evidence and automatically verifying an interpretation are different operations.

Change one variable

TestVerifyFix replaces SlowRepository with FastRepository while retaining the same handler, service, and "1y" input. The fast repository always sleeps for 10 ms and returns the same one-order payload.

This controlled replacement isolates the artificial repository delay. It does not demonstrate a SQL optimization or a production deployment. Both implementations visibly return the same data, but the tests do not assert payload correctness.

The verification assertion from main_test.go is:

if res.TotalDuration > 100*time.Millisecond {
    t.Fatalf("expected request to be fast (< 100ms), but took %v", res.TotalDuration)
}

The condition accepts a total duration of at most 100 ms, including exactly 100 ms. That is a lab test threshold, not a production SLO or latency guarantee. Because these are wall-clock tests, execution conditions can influence the result.

Keep the conclusion inside the evidence

All three tests use "1y" and context.Background(). They do not test the 1m path, returned order contents, HTTP status codes, concurrent load, or cancellation.

Although context is passed through the call chain, neither repository checks it, and the sleeps are not cancellation-aware. A context parameter alone does not establish timeout behavior.

The error path also deserves careful reading. The service returns the repository error, but the handler returns an empty RequestResult on error. Timing is therefore not returned on that path. Both provided repositories always return a nil error, and no test injects a failing repository. These are possible follow-up checks, not existing capabilities.

The reusable debugging loop

1. Define the exact condition you can reproduce.
2. Separate implementation facts, documentation examples, and assumptions.
3. Write hypotheses with evidence that could refute them.
4. Check the boundaries and overlap of your measurements.
5. Change one variable and verify against an explicit criterion.
6. State what the experiment did not establish.

For this lab, the source identifies a four-second artificial repository delay. That is a useful, bounded conclusion. Claiming a missing production index would go beyond the evidence.

The point is not to sound certain sooner. It is to make each conclusion traceable to the code, measurement, or controlled change that supports it.

Source

Software Engineering Lab 11: README.md, main.go, and main_test.go, inspected at commit 82af988b89439fa92b1200406c5afbd59ce72a56. The repository root supplies go.mod. Code excerpts belong in the existing lab package; they are not standalone programs.