Stage 7 · Master
Phase 18 — Performance Engineering
Profiling
Mount net/http/pprof on an internal-only port, capture CPU and heap profiles under real traffic, and read go tool pprof's top and flame-graph views to find where organization-service actually spends its time.
A Benchmark Says Something Is Slow; a Profile Says Where
Lesson 4's benchmark shows ListWithProfiles at 250 members allocates 2,803 times per call and takes 9.8ms. That number alone does not say which line causes 2,803 allocations — it could be the map construction, the JSON marshaling of the response, or something in a dependency nobody suspects. Profiling attributes CPU time and allocations to actual call stacks, replacing a guess with a measurement.
Mount net/http/pprof on an Internal Port, Never the Public One
Observability already moved organization-service's operational endpoints off the public engine and onto a second, cluster-internal listener — that argument is settled and not repeated here. What is new is that pprof raises the stakes of getting it wrong. A metrics scrape leaks counters; a heap profile leaks fragments of in-flight request data. So pprof joins the existing internal listener rather than adding a third port, and it is registered explicitly rather than through the side-effect import's DefaultServeMux registration.
import (
"net/http"
+ "net/http/pprof"
"time"
)
func newInternalServer(metricsHandler http.Handler) *http.Server {
mux := http.NewServeMux()
mux.Handle("/metrics", metricsHandler)
+ mux.HandleFunc("/debug/pprof/", pprof.Index)
+ mux.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)
+ mux.HandleFunc("/debug/pprof/profile", pprof.Profile)
+ mux.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
+ mux.HandleFunc("/debug/pprof/trace", pprof.Trace)
return &http.Server{
Addr: ":9090",
Handler: mux,
- WriteTimeout: 10 * time.Second,
+ WriteTimeout: 35 * time.Second,
}
}The timeout change is the line most people miss. A 30-second CPU profile written to a listener with a 10-second write timeout returns a truncated file that pprof refuses to parse, and the resulting error says nothing about timeouts. Registering the handlers on the existing explicit mux — rather than importing pprof for its side effect — also means a stray http.ListenAndServe(addr, nil) elsewhere in the binary cannot expose these routes by accident.
A heap profile can contain fragments of in-flight request data — including, in the worst case, a resident's session token captured mid-request. Lesson 11 of Production Deployment restricts this port at the network-policy layer too; the application-level separation here is the first, not the only, control.
Capture a Profile While the Slow Behavior Is Actually Happening
A profile taken against an idle process measures idling. The membership-listing endpoint from Lessons 2 and 4 is exercised with the same load generator built for Lesson 3's pool-exhaustion reproduction, and a 30-second CPU profile is captured from the internal port while that load runs.
Showing nodes accounting for 4.71s, 89.06% of 5.29s total
flat flat% sum% cum cum%
1.92s 36.30% 36.30% 1.92s 36.30% encoding/json.(*structEncoder).encode
0.88s 16.64% 52.94% 0.88s 16.64% runtime.mallocgc
0.61s 11.53% 64.47% 1.41s 26.65% reflect.Value.Field
0.54s 10.21% 74.67% 2.68s 50.66% github.com/hoa-platform/backend/services/organization/internal/adapter/http.(*MembershipHandler).ServeHTTP
0.41s 7.75% 82.42% 0.41s 7.75% encoding/json.stringEncoder36% of CPU time in encoding/json's reflection-based struct encoder is the single largest node — larger than the database query path itself, which does not even appear in the top five. The batched-query fix from Lesson 2 was real, but it was never the biggest cost in this specific endpoint.
Distinguish flat% From cum% Before Deciding What to Fix
- flat: time spent in that function's own code, excluding functions it calls — json.(*structEncoder).encode's 36.30% is time the encoder itself burns, mostly on reflection.
- cum: time spent in that function plus everything it calls — ServeHTTP's 50.66% cum% includes the JSON encoding it triggers, which is why a handler function can show a large cum% while doing very little flat work itself.
- A fix targets the highest flat% node first — it is the one whose own code, not a callee's, is actually consuming CPU cycles.
Replace Reflection-Based Encoding With a Generated Encoder
encoding/json's default Marshal uses reflection to inspect struct tags on every call. MemberView never changes shape at runtime, which makes it a candidate for easyjson-style code generation that emits a hand-written encoder — eliminating the reflection cost entirely for exactly this hot type, without touching every other JSON response in the codebase.
Showing nodes accounting for 2.98s, 84.12% of 3.54s total
flat flat% sum% cum cum%
0.71s 20.06% 20.06% 0.71s 20.06% github.com/hoa-platform/backend/services/organization/internal/dto.(*MemberView).MarshalJSON
0.66s 18.64% 38.70% 0.66s 18.64% runtime.mallocgc
0.54s 15.25% 53.95% 1.10s 31.07% github.com/hoa-platform/backend/services/organization/internal/adapter/http.(*MembershipHandler).ServeHTTPTotal profiled time dropped from 5.29s to 3.54s for the same 30-second window and load pattern — the generated encoder's flat% is now smaller than reflection's was, and reflect.Value.Field no longer appears in the top nodes at all.
A CPU Profile Cannot Diagnose Memory Growth or Goroutine Leaks
| Profile | Endpoint | Answers |
|---|---|---|
| CPU | /debug/pprof/profile?seconds=30 | Where are cycles spent during an active window? |
| Heap | /debug/pprof/heap | What is currently allocated and retained — is a cache or buffer growing without bound? |
| Goroutine | /debug/pprof/goroutine | Are goroutines accumulating instead of exiting — a leak that shows up as memory and scheduler pressure, not CPU time? |
A memory-growth incident earlier in the platform's life (the summary cache from Part 7 briefly leaked entries under a specific eviction bug) was diagnosed with go tool pprof -inuse_space http://localhost:9090/debug/pprof/heap taken twice, an hour apart, and compared with go tool pprof -base — the same statistical-comparison instinct as benchstat, applied to memory instead of CPU.
Applied exercise
Profile the keyset pagination endpoint under load
Lesson 4's benchmark exercise measured the keyset-pagination rewrite in isolation; production traffic on the same endpoint has not been profiled.
- Mount the internal-only pprof server if not already running, and confirm it is unreachable from the public listener.
- Run the load generator against the flats list endpoint and capture a 30-second CPU profile.
- Identify the highest flat% node and state whether it is inside this platform's own code or a standard-library/dependency function.
- Propose one concrete fix based on the profile, and state what a second profile after the fix should show if the fix worked.
Deliverable
A saved cpu.pprof file, a written top-nodes analysis distinguishing flat% from cum%, and a specific, falsifiable prediction for the post-fix profile.
Completion checks
- The load generator and the profile capture overlap in time, not sequentially with idle time in between.
- The analysis explicitly separates flat% from cum% rather than treating them as interchangeable.
- The proposed fix targets the actual highest-flat%-node, not a guess based on the code's appearance alone.
Why is net/http/pprof mounted on a separate internal-only server instead of the public API's ServeMux?
Mark this lesson complete to store local progress and unlock a cleaner resume path the next time you visit.