Go's execution tracer

Go's tools can help you diagnose problems with your applications—if you can wield them effectively. The Execution Tracer provides great visibility into the scheduler, to help solve timing dependent bugs and track down latency problems. Learn how to use the tools before you have a time-critical need.

Transcript

1. Go's execution tracer
   the pprof endpoint you haven't used yet
   

   View Slide

2. $ 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.
   

   View Slide

3. $ go doc cmd/trace
   Trace is a tool for viewing trace files.
   ...
   View the trace in a web browser:
   go tool trace trace.out
   

   View Slide

4. The tool in three demos:
   1. A timing-dependent bug
   2. What it doesn't show
   3. Latency during GC
   

   View Slide

5. #1: Canceling requests
   

   View Slide

6. "Cancelation is transitive"
   https://talks.golang.org/2014/gotham-context.slide#6
   

   View Slide

7. "Cancelation is transitive"
   https://talks.golang.org/2014/gotham-context.slide#6
   

   View Slide

8. import _ "net/http/pprof"
   import "runtime/trace"
   // ...
   trace.Start(w)
   defer trace.Stop()
   

   View Slide

9. $ go tool trace trace.out
   

   View Slide

10. View Slide

11. View Slide

12. 330µs
    

    View Slide

13. View Slide

14. G564 G466 G650
    G649
    G648
    G18
    

    View Slide

15. 750 milliseconds earlier ...
    

    View Slide

16. blocked on
    net.(*netFD).Read
    "closeNotifyAwaitActivityRead"
    

    View Slide

17. srv := &http.Server{
    ReadTimeout: 750 * time.Millisecond,
    // ...
    }
    

    View Slide

18. blocked on
    net.(*netFD).Read
    "closeNotifyAwaitActivityRead"
    

    View Slide

19. #2: It's not a panacea
    

    View Slide

20. View Slide

21. user code in
    goroutines
    runtime work
    on the bottom syscall
    SWEEP to
    help GC
    

    View Slide

22. memory allocation
    

    View Slide

23. Classic GC advice:
    "allocate less memory"
    

    View Slide

24. statsd package
    uses locks
    not saturated!
    

    View Slide

25. 5.4s of waiting
    in a 2s profile
    

    View Slide

26. #3: Sometimes it is the GC
    

    View Slide

27. GC
    

    View Slide

28. goroutines
    in queue
    9ms delay
    

    View Slide

29. 9000µs 200µs
    50µs
    50µs
    

    View Slide

30. Check golang.org/issue
    found #14812,
    filed #16432
    

    View Slide

31. 1. Allocation is counter to GC
    2. Must assist (or steal credit)
    3. Can't steal early in GC
    4. Assists are amortized
    5. 12MB minimum assist*
    * based on concurrent GC pacing
    

    View Slide

32. 50µs
    50µs 50µs
    

    View Slide

33. go tool trace
    http://.../debug/pprof/trace
    

    View Slide

34. More details on the GC bug,
    soon on blog.twitch.tv
    

    View Slide

35. How can the tool help you?
    1. See time-dependent issues
    2. Complements other profiles
    3. Find latency improvements
    

    View Slide

36. Be prepared:
    practice using the tools
    Thank you!
    

    View Slide