You, latency and profiling @ GolangUK 2017

Transcript

1. 1.

   You, latency and profiling Filippo Valsorda — @FiloSo/le

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 ms
7. 7.

   A fast website… … can handle many requests … or

   loads in a few milliseconds
8. 8.

   A fast API… … can handle many clients … or

   answers in a few milliseconds
9. 9.

   Fast is… Throughput and Latency

10. 10.

    CPU profiling -cpuprofile 
 /debug/pprof/profile

11. 11.

    SIGPROF CPU profiling

12. 12.

    runtime/proc.go

13. 13.

    h>p.Handler 1 Running on CPU h>p.Handler 2 I/O I/O h>p.Handler

    3 I/O h>p.Handler 4 I/O CPU profiling
14. 14.

    Running on CPU I/O I/O I/O I/O h>p.Handler 1 h>p.Handler

    2 h>p.Handler 3 h>p.Handler 4 CPU profiling
15. 15.

    I/O Observed latency h>p.Handler 1 CPU profiling

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 execuOon events: • gorouOne

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

    •log files are BIG •25% overhead (aWer Go 1.7) •symbols

    are embedded (Go 1.7) The tracer
26. 26.

    •Full event context •GorouOne metadata and history •Discrete events, not

    samples Trace vs. profile
27. 27.

    CPU profiling Total: 20 samples

28. 28.

    Tracing events

29. 29.

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

30. 30.

    None
31. 31.

    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
32. 32.

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

    -web syscall.pprof
33. 33.

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

    && 
 open torch.svg
34. 34.

    None
35. 35.

    None
36. 36.

    -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() } }
37. 37.

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

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

    -pprof=sync

39. 39.

    -pprof=sync

40. 40.

    -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 }
41. 41.

    -pprof=net

42. 42.

    -pprof=net

43. 43.

    -pprof=net

44. 44.

    None
45. 45.

    WriIng 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)
46. 46.

    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) }
47. 47.

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

48. 48.

    None
49. 49.

    None
50. 50.

    Build more tools! • Focus on gorouOne number • Aggregate

    all blocking types • VisualizaOons • …
51. 51.

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

52. 52.

    None
53. 53.

    Build more tools! Profile latency!

54. 54.

    QuesIons? Filippo Valsorda @FiloSo/le hi@filippo.io