You, latency and profiling @ GopherCon India 2017

Transcript

1. You, latency and profiling
   Filippo Valsorda — @FiloSottile
   

   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
   milliseconds
   

   View Slide

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

   View Slide

8. A fast API…
   … can handle many clients at the
   same time
   … 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. CPU profiling
    SIGPROF
    

    View Slide

12. runtime/proc.go
    

    View Slide

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
    

    View Slide

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
    

    View Slide

15. CPU profiling
    I/O
    Observed latency
    http.Handler 1
    

    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
    execution events:
    • goroutine scheduling, blocking
    • syscalls, network, I/O
    • garbage collection
    

    View Slide

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

    View Slide

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

    View Slide

27. The tracer
    import "runtime/trace"
    

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

    View Slide

28. View Slide

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
    

    View Slide

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

    View Slide

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

    open torch.svg
    

    View Slide

32. View Slide

33. View Slide

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

    View Slide

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

    View Slide

36. -pprof=sync
    

    View Slide

37. -pprof=sync
    

    View Slide

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
    }
    

    View Slide

39. -pprof=net
    

    View Slide

40. -pprof=net
    

    View Slide

41. View Slide

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)
    

    View Slide

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

    View Slide

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

    View Slide

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

    

    github.com/FiloSottile/tracetools
    

    View Slide

46. View Slide

47. View Slide

48. Build more tools!
    • Focus on goroutine number
    • Aggregate all blocking types
    • Visualizations
    • …
    

    View Slide

49. tracehist

    tracehist -filter=Close trace.out 

    

    github.com/FiloSottile/tracetools
    

    View Slide

50. View Slide

51. Build more tools!
    Profile latency!
    

    View Slide

52. Questions?
    Filippo Valsorda
    @FiloSottile
    filippo@cloudflare.com
    

    View Slide