You, latency and profiling @ GopherCon India 2017

You, latency and profiling @ GopherCon India 2017

9fdab9d005b82612cadbfe699b541f83?s=128

Filippo Valsorda

February 25, 2017
Tweet

Transcript

  1. 6.

    A fast database… … can store many GB per second

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

    A fast website… … can handle many requests at the

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

    A fast API… … can handle many clients at the

    same time … or answers in a few milliseconds
  4. 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
  5. 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
  6. 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) } }
  7. 18.
  8. 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
  9. 22.
  10. 23.
  11. 24.

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

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

    The tracer • log files are BIG • 25% overhead

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

    Trace vs. profile • Full event context • Goroutine metadata

    and history • Discrete events, not samples
  14. 28.
  15. 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
  16. 32.
  17. 33.
  18. 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() } }
  19. 35.
  20. 38.
  21. 41.
  22. 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)
  23. 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) }
  24. 46.
  25. 47.
  26. 48.

    Build more tools! • Focus on goroutine number • Aggregate

    all blocking types • Visualizations • …
  27. 50.