You, latency and profiling @ GopherCon India 2017

Transcript

1. 1.

   You, latency and profiling Filippo Valsorda — @FiloSottile

2. 2.

   What is fast?

3. 3.

   A fast hash… … can hash many MB per second

4. 4.

   A fast regex… … can process many MB/s

5. 5.

   A fast database… … can store many GB per second

6. 6.

   A fast database… … can store many GB per second

   … or replies to queries in a few milliseconds
7. 7.

   A fast website… … can handle many requests at the

   same time … or loads in a few milliseconds
8. 8.

   A fast API… … can handle many clients at the

   same time … or answers in a few milliseconds
9. 9.

   Fast is… Throughput and Latency

10. 10.

    CPU profiling -cpuprofile 
 /debug/pprof/profile

11. 11.

    CPU profiling SIGPROF

12. 12.

    runtime/proc.go

13. 13.

    CPU profiling http.Handler 1 Running on CPU http.Handler 2 I/O

    I/O http.Handler 3 I/O http.Handler 4 I/O
14. 14.

    CPU profiling Running on CPU I/O I/O I/O I/O http.Handler

    1 http.Handler 2 http.Handler 3 http.Handler 4
15. 15.

    CPU profiling I/O Observed latency http.Handler 1

16. 16.

    func Write(data []byte) { for i := 0; i <

    50; i++ { tmpfile, _ := ioutil.TempFile("", "ex") defer os.Remove(tmpfile.Name()) _, err = tmpfile.Write(data) tmpfile.Close() } } func Hash(data []byte) { for i := 0; i < 50; i++ { sha256.Sum256(data) } }
17. 17.

    $ time curl http://127.0.0.1:12345/hash-and-write
 9.831 total
 go tool pprof -web

    slowserver cpu.pprof
18. 18.

    None
19. 19.

    $ time curl http://127.0.0.1:12345/hash-and-write
 9.831 total
 
 
 $ time

    curl http://127.0.0.1:12345/write-no-hash
 7.692 total
20. 20.

    Latency is not all about CPU

21. 21.

    CPU profiling is for throughput The tracer is for latency

22. 22.

    $ time curl http://127.0.0.1:12345/write-no-hash
 7.692 total
 go tool trace -pprof=syscall

    trace.out > syscall.pprof go tool pprof -web syscall.pprof
23. 23.

    None
24. 24.

    The tracer Detailed nanosecond-level log of execution events: • goroutine

    scheduling, blocking • syscalls, network, I/O • garbage collection
25. 25.

    The tracer • log files are BIG • 25% overhead

    (after Go 1.7) • symbols are embedded (Go 1.7)
26. 26.

    Trace vs. profile • Full event context • Goroutine metadata

    and history • Discrete events, not samples
27. 27.

    The tracer import "runtime/trace" 
 import "net/http/pprof" /debug/pprof/trace?seconds=5

28. 28.

    None
29. 29.

    go tool trace -pprof=TYPE trace.out Supported profile types are: -

    net: network blocking profile - sync: synchronization blocking profile - syscall: syscall blocking profile - sched: scheduler latency profile
30. 30.

    go tool trace -pprof=syscall trace.out > syscall.pprof go tool pprof

    -web syscall.pprof
31. 31.

    go tool trace -pprof=syscall trace.out > syscall.pprof go-torch -b syscall.pprof

    && 
 open torch.svg
32. 32.

    None
33. 33.

    None
34. 34.

    -pprof=syscall func Write(data []byte) { for i := 0; i

    < 50; i++ { tmpfile, _ := ioutil.TempFile("", "ex") defer os.Remove(tmpfile.Name()) _, err = tmpfile.Write(data) tmpfile.Close() } }
35. 35.

    -pprof=sync // Block waits on a channel func Block() {

    <-time.After(1 * time.Second) }
36. 36.

    -pprof=sync

37. 37.

    -pprof=sync

38. 38.

    -pprof=net func Download() []byte { r, err := http.Get("https://golang.org/doc/go1.8") body,

    err := ioutil.ReadAll(r.Body) r.Body.Close() return body }
39. 39.

    -pprof=net

40. 40.

    -pprof=net

41. 41.

    None
42. 42.

    Writing our own profile prof := make(map[uint64]pprof.Record) for _, ev

    := range events { if ev.Type != trace.EvGoBlockNet { continue } rec := prof[ev.StkID] rec.Stk = ev.Stk rec.N++ rec.Time += ev.Link.Ts - ev.Ts prof[ev.StkID] = rec } pprof.BuildProfile(prof).Write(os.Stdout)
43. 43.

    var childG = make(map[uint64]struct{}) var lastGLen int for { for

    _, ev := range events { if ev.Type != trace.EvGoCreate { continue } if _, ok := childG[ev.G]; !ok && !filterStack(ev.Stk, re) { continue } childG[ev.Args[0]] = struct{}{} } if len(childG) == lastGLen { break } lastGLen = len(childG) }
44. 44.

    if _, ok := childG[ev.G]; !ok && !filterStack(ev.Stk, re) {

    continue }
45. 45.

    tracefocus tracefocus -filter=ServeHTTP trace.out > net.pprof
 
 github.com/FiloSottile/tracetools

46. 46.

    None
47. 47.

    None
48. 48.

    Build more tools! • Focus on goroutine number • Aggregate

    all blocking types • Visualizations • …
49. 49.

    tracehist
 tracehist -filter=Close trace.out 
 
 github.com/FiloSottile/tracetools

50. 50.

    None
51. 51.

    Build more tools! Profile latency!

52. 52.

    Questions? Filippo Valsorda @FiloSottile filippo@cloudflare.com