You, latency and profiling @ GolangUK 2017

Transcript

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

   View Slide

2. What is fast?
   

   View Slide

3. A fast hash…
   … can hash many MB per second
   

   View Slide

4. A fast regex…
   … can process many MB/s
   

   View Slide

5. A fast database…
   … can store many GB per second
   

   View Slide

6. A fast database…
   … can store many GB per second
   … or replies to queries in a few ms
   

   View Slide

7. A fast website…
   … can handle many requests
   … or loads in a few milliseconds
   

   View Slide

8. A fast API…
   … can handle many clients
   … or answers in a few milliseconds
   

   View Slide

9. Fast is…
   Throughput
   and
   Latency
   

   View Slide

10. CPU profiling
    -cpuprofile
    

    /debug/pprof/profile
    

    View Slide

11. SIGPROF
    CPU profiling
    

    View Slide

12. runtime/proc.go
    

    View Slide

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
    

    View Slide

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
    

    View Slide

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

    View Slide

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

    View Slide

17. $ time curl http://127.0.0.1:12345/hash-and-write

    9.831 total

    go tool pprof -web slowserver cpu.pprof
    

    View Slide

18. View Slide

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
    

    View Slide

20. Latency
    is not all about CPU
    

    View Slide

21. CPU profiling is for throughput
    The tracer is for latency
    

    View Slide

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
    

    View Slide

23. View Slide

24. The tracer
    Detailed nanosecond-level log of
    execuOon events:
    • gorouOne scheduling, blocking
    • syscalls, network, I/O
    • garbage collecOon
    

    View Slide

25. •log files are BIG
    •25% overhead (aWer Go 1.7)
    •symbols are embedded (Go 1.7)
    The tracer
    

    View Slide

26. •Full event context
    •GorouOne metadata and history
    •Discrete events, not samples
    Trace vs. profile
    

    View Slide

27. CPU profiling
    Total: 20 samples
    

    View Slide

28. Tracing events
    

    View Slide

29. import "runtime/trace"
    

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

    View Slide

30. View Slide

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
    

    View Slide

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

    View Slide

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

    open torch.svg
    

    View Slide

34. View Slide

35. View Slide

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

    View Slide

37. -pprof=sync
    // Block waits on a channel
    func Block() {
    <-time.After(1 * time.Second)
    }
    

    View Slide

38. -pprof=sync
    

    View Slide

39. -pprof=sync
    

    View Slide

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
    }
    

    View Slide

41. -pprof=net
    

    View Slide

42. -pprof=net
    

    View Slide

43. -pprof=net
    

    View Slide

44. View Slide

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)
    

    View Slide

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

    View Slide

47. tracefocus
    tracefocus -filter=ServeHTTP trace.out >
    net.pprof

    

    github.com/FiloSottile/tracetools
    

    View Slide

48. View Slide

49. View Slide

50. Build more tools!
    • Focus on gorouOne number
    • Aggregate all blocking types
    • VisualizaOons
    • …
    

    View Slide

51. tracehist

    tracehist -filter=Close trace.out 

    

    github.com/FiloSottile/tracetools
    

    View Slide

52. View Slide

53. Build more tools!
    Profile latency!
    

    View Slide

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

    View Slide