An Introduction to "go tool trace"

The execution tracer (go tool trace) is one of Go's most powerful diagnosis tools, but its power and complexity make it difficult to learn. See how it can help you understand goroutines' interactions in great detail, uncovering latency bugs and logical races.

Transcript

1. go tool trace for correct and effective concurrency
2. Let's talk about Go
3. Let's talk about go
4. A special tool for Go's needs * and Chromium
5. goroutine scheduling instrumented
6. Concurrency, and how to manage it
7. Parallelism, and how to exploit it
8. $ go doc runtime/trace package trace // import "runtime/trace" Go execution tracer. The tracer captures a wide range of execution events ... A trace can be analyzed later with 'go tool trace' command.
9. $ go doc cmd/trace Trace is a tool for viewing trace files. ... View the trace in a web browser: go tool trace trace.out
10. pp-quiet-10.first.trace.redacted.html
11. grpc.pre-1005-5.exectrace
12. The tool in three demos: 1. A timing-dependent bug 2. What it doesn't show 3. Latency during GC
13. #1: A race condition
14. go test -race go build -race go install -race
15. ================== WARNING: DATA RACE Read at 0x00c420141500 by goroutine 27: ... Previous write at 0x00c420141500 by goroutine 26: ...
16. a logical race, not a data race
17. gRPC, HTTP/2, and flow control
18. grpc.pre-1005-5.exectrace stuff happening stuff not happening
19. $ go tool trace trace.out $ go test -trace=trace.out
20. "View trace"
21. grpc.pre-1005-5.exectrace 1s (from context.WithTimeout)
22. grpc.pre-1005-5.exectrace
23. grpc.pre-1005-5.exectrace Garbage collection 20ms Goroutines running on OS threads
24. "Sync blocking profile"
25. grpc.pre-1005-5.exectrace
26. grpc.pre-1005-5.exectrace one-second unexpected delay
27. grpc.pre-1005-5.exectrace goroutine "name"
28. "Goroutine analysis"
29. grpc.pre-1005-5.exectrace
30. grpc.pre-1005-5.exectrace
31. grpc.pre-1005-5.exectrace 1s
32. grpc.pre-1005-5.exectrace
33. grpc.pre-1005-5.exectrace
34. func wait(ctx context.Context, ..., proceed <-chan int) (int, error) { select { case <-ctx.Done(): // ... case ...: // stream closed, etc case i := <-proceed: return i, nil } }
35. t.sendQuotaPool.add(0) tq, err := wait(s.ctx, ..., t.sendQuotaPool.acquire()) if err != nil && ... { t.sendQuotaPool.cancel() return } // calculate payload size ... t.sendQuotaPool.add(tq-ps)
36. type quotaPool struct { c chan int mu sync.Mutex quota int }
37. func newQuotaPool(q int) *quotaPool { qb := &quotaPool{ c: make(chan int, 1), } if q > 0 { qb.c <- q } else { qb.quota = q } return qb }
38. func newQuotaPool(q int) *quotaPool { qb := &quotaPool{ c: make(chan int, 1), } if q > 0 { qb.c <- q } else { qb.quota = q } return qb }
39. func newQuotaPool(q int) *quotaPool { qb := &quotaPool{ c: make(chan int, 1), } if q > 0 { qb.c <- q } else { qb.quota = q } return qb }
40. func newQuotaPool(q int) *quotaPool { qb := &quotaPool{ c: make(chan int, 1), } if q > 0 { qb.c <- q } else { qb.quota = q } return qb }
41. type quotaPool struct { c chan int // positive quota here mu sync.Mutex quota int // zero or negative quota }
42. func (qb *quotaPool) acquire() <-chan int { return qb.c }
43. func (qb *quotaPool) add(n int) { qb.mu.Lock(); defer qb.mu.Unlock() if qb.quota += n; qb.quota <= 0 { return } select { case qb.c <- qb.quota: qb.quota = 0 default: } }
44. func (qb *quotaPool) cancel() { qb.mu.Lock(); defer qb.mu.Unlock() select { case n := <-qb.c: qb.quota += n default: } }
45. Goroutine 10: pool.add(0) wait(..., pool.aq()) pool.add(tq-ps)
46. Goroutine 300: pool.add(0) wait(..., pool.aq()) pool.cancel() Goroutine 400: pool.add(0) wait(..., pool.aq()) pool.add(tq-ps)
47. Goroutine 5000: pool.add(0) wait(..., pool.aq()) pool.add(tq-ps) Goroutine 6000: pool.add(0) wait(..., pool.aq()) pool.add(tq-ps)
48. grpc.pre-1005-5.exectrace G8006, about to stall for one second G7962, another goroutine running the same function 36µs
49. Goroutine 7962: pool.add(0) wait(..., pool.aq()) pool.cancel() Goroutine 8006: pool.add(0) wait(..., pool.aq()) pool.cancel()
50. - func (qb *quotaPool) cancel() { - qb.mu.Lock(); defer qb.mu.Unlock() - - select { - case n := <-qb.c: - qb.quota += n - default: - } - }
51. func (qb *quotaPool) add(v int) { qb.mu.Lock(); defer qb.mu.Unlock() select { case n := <-qb.c: qb.quota += n default: } if qb.quota += v; qb.quota > 0 { qb.c <- qb.quota qb.quota = 0 } }
52. func (qb *quotaPool) add(v int) { qb.mu.Lock(); defer qb.mu.Unlock() select { case n := <-qb.c: qb.quota += n default: } if qb.quota += v; qb.quota > 0 { qb.c <- qb.quota qb.quota = 0 } }
53. #2: It's not a panacea
54. Three ways to get data: 1. Testing with -trace flag 2. Direct runtime/trace use 3. net/http/pprof handlers
55. pp-quiet-10.first.trace.redacted.html suspicious gaps every five seconds garbage collection unlike other goroutines
56. pp-quiet-10.first.trace.redacted.html nothing else runs during these 90ms
57. runtime.ReadMemStats • and Go 1.8 or earlier • and large (40GB) heap • leads to long pauses (fixed in Go 1.9)
58. pp-quiet-10.first.trace.redacted.html what does this goroutine do? how does it spend its CPU time? can it run more efficiently? can it finish sooner (parallelism)?
59. pp-quiet-10.first.trace.redacted.html net/http.(*conn).serve what request did it serve? which handler func ran? what status code was returned?
60. #3: The GC is still improving
61. tc.1.third.trace.redacted.html patchy network long run queue some behavior is different during GC * this is probably bad, but how good should we expect?
62. Go garbage collection timeline: Go 1: program fully stopped Go 1.1: GC uses parallel threads Go 1.4: precise collection Go 1.5: global pauses <10ms Go 1.8: goroutine pauses <100µs
63. garbage collection Go 1 GC whole program stopped ("STW") user code ("mutator")
64. user code ("mutator") garbage collection Go 1.1 GC whole program stopped ("STW")
65. garbage collection Go 1.5 GC user code ("mutator") whole program stopped ("STW")
66. garbage collection Go 1.8 GC whole program stopped ("STW") user code ("mutator")
67. #3A: Stop-The-World pauses
68. Everything stops when the GC begins and ends mark phase Stopping everything takes time
69. ta.nopreempt-2.fourth.trace.redacted.html GC begins stragglers GC really begins 3.6ms unused CPU
70. Goroutines can stop when... ✓ allocating memory ✓ calling functions ✓ communicating ✗ crunching numbers in a loop
71. Seen in: • encoding/base64 • encoding/json • .../golang/protobuf/proto it's measurable for 1MB values ... if you're looking for it * check code lines before "End Stack Trace"
72. go func() { for i := 0; i < 1e9; i++ { } } Or write your own tight loop:
73. golang.org/issue/10958 The Go 1.10 compiler should have a general, permanent fix Workaround available now
74. ta.preempt-2.second.trace.redacted.html quick pauses, less waste
75. #3B: Other awkward pauses
76. A mark/sweep GC: • "mark" finds in-use memory • "sweep" reclaims the rest
77. GC needs to make progress User code works against that User code is forced to help out
78. tc.1.third.trace.redacted.html read(2) syscall * hold 'shift' to draw a selection box user code in goroutines runtime work below helping the GC
79. tc.1.third.trace.redacted.html this assist ran for 4.4ms
80. tc.1.third.trace.redacted.html this assist ran for 15.6ms ... and didn't even finish
81. Most assists are well-deserved But they start suddenly Sweeping requires assists too Don't allocate in critical paths?
82. go tool trace http://.../debug/pprof/trace
83. How can the tool help you? 1. See time-dependent issues 2. Complements other profiles 3. Find latency improvements
84. Be prepared: practice using the tools Thank you! @rhyshiltner