You, latency and profiling @ GolangUK 2017

You, latency and profiling @ GolangUK 2017

9fdab9d005b82612cadbfe699b541f83?s=128

Filippo Valsorda

August 17, 2017
Tweet

Transcript

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

  2. What is fast?

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

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

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

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

    … or replies to queries in a few ms
  7. A fast website… … can handle many requests … or

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

    answers in a few milliseconds
  9. Fast is… Throughput and Latency

  10. CPU profiling -cpuprofile 
 /debug/pprof/profile

  11. SIGPROF CPU profiling

  12. runtime/proc.go

  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. 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. I/O Observed latency h>p.Handler 1 CPU profiling

  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. $ time curl http://127.0.0.1:12345/hash-and-write
 9.831 total
 go tool pprof -web

    slowserver cpu.pprof
  18. None
  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. Latency is not all about CPU

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

  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. None
  24. The tracer Detailed nanosecond-level log of execuOon events: • gorouOne

    scheduling, blocking • syscalls, network, I/O • garbage collecOon
  25. •log files are BIG •25% overhead (aWer Go 1.7) •symbols

    are embedded (Go 1.7) The tracer
  26. •Full event context •GorouOne metadata and history •Discrete events, not

    samples Trace vs. profile
  27. CPU profiling Total: 20 samples

  28. Tracing events

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

  30. None
  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. go tool trace -pprof=syscall trace.out > syscall.pprof go tool pprof

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

    && 
 open torch.svg
  34. None
  35. None
  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. -pprof=sync // Block waits on a channel func Block() {

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

  39. -pprof=sync

  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. -pprof=net

  42. -pprof=net

  43. -pprof=net

  44. None
  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. 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. tracefocus tracefocus -filter=ServeHTTP trace.out > net.pprof
 
 github.com/FiloSottile/tracetools

  48. None
  49. None
  50. Build more tools! • Focus on gorouOne number • Aggregate

    all blocking types • VisualizaOons • …
  51. tracehist
 tracehist -filter=Close trace.out 
 
 github.com/FiloSottile/tracetools

  52. None
  53. Build more tools! Profile latency!

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