Using Go 1.10 new trace features to debug an integration test

My toy example for this post

Generate a CPU profile

go test -cpuprofile cpu.prof
(pprof) top1
Showing nodes accounting for 810ms, 82.65% of 980ms total
Showing top 1 nodes out of 81
flat flat% sum% cum cum%
810ms 82.65% 82.65% 820ms 83.67% github.com/cep21/trace-110.takeCPU
(pprof) top1 -cum
Showing nodes accounting for 810ms, 82.65% of 980ms total
Showing top 1 nodes out of 81
flat flat% sum% cum cum%
810ms 82.65% 82.65% 820ms 83.67% github.com/cep21/trace-110.takeCPU

View the CPU profile in a web UI (new in 1.10)

go1.10beta1 tool pprof -http=localhost:12345 cpu.prof
Nope, still showing cpu usage

Generate a blocking profile (improved in 1.10)

go test —blockprofile=block.out
< go tool pprof block.out 
Main binary filename not available.
Type: delay
Entering interactive mode (type “help” for commands, “o” for options)
(pprof) top
Showing nodes accounting for 12.65s, 100% of 12.65s total
flat flat% sum% cum cum%
12.65s 100% 100% 12.65s 100% <unknown>
< go1.10beta1 test -blockprofile=block.out
.....
< go1.10beta1 tool pprof block.out
(pprof) top
Showing nodes accounting for 12.34s, 100% of 12.34s total
Dropped 31 nodes (cum <= 0.06s)
Showing top 10 nodes out of 32
flat flat% sum% cum cum%
4.21s 34.09% 34.09% 4.21s 34.09% runtime.chanrecv1
4.13s 33.46% 67.55% 4.13s 33.46% runtime.selectgo
4.01s 32.45% 100% 4.01s 32.45% sync.(*WaitGroup).Wait
0 0% 100% 4.01s 32.45% github.com/cep21/trace-110.TestServer
0 0% 100% 4.01s 32.45% github.com/cep21/trace-110.startServer
0 0% 100% 4s 32.40% github.com/cep21/trace-110.takeIO

Generate a trace

go test -trace trace.out
go1.10beta1 tool trace trace.out
The initial UI
Too much!
Full network blocking profile

Limit to a goroutine (improved in 1.10)

Small execution time, large total time
There’s an arrow!
> go1.10beta1 tool pprof 'http://127.0.0.1:53668/block?id=19105152&raw=1'Fetching profile over HTTP from http://127.0.0.1:53668/block?id=19105152&raw=1
Saved profile in /Users/jlindamo/pprof/pprof.contentions.delay.005.pb.gz
Type: delay
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 4112.05ms, 100% of 4112.28ms total
Dropped 4 nodes (cum <= 20.56ms)
Showing top 10 nodes out of 13
flat flat% sum% cum cum%
4112.05ms 100% 100% 4112.05ms 100% runtime.selectgo
0 0% 100% 4112.28ms 100% github.com/cep21/trace-110.takeIO
0 0% 100% 4112.28ms 100% net/http.(*Client).Do
0 0% 100% 4112.28ms 100% net/http.(*Client).Get
0 0% 100% 4112.28ms 100% net/http.(*Client).send
0 0% 100% 4112.28ms 100% net/http.(*Transport).RoundTrip
0 0% 100% 380.97ms 9.26% net/http.(*Transport).getConn
go get github.com/google/pprof
> pprof -http "localhost:12345" 'http://127.0.0.1:53668/block?id=19105152&raw=1'
Click on flame graph
Flamegraph of the example

--

--

Get the Medium app

A button that says 'Download on the App Store', and if clicked it will lead you to the iOS App store
A button that says 'Get it on, Google Play', and if clicked it will lead you to the Google Play store