You, latency and profiling @ GolangUK 2017

Slide 1

Slide 1 text

You, latency and proﬁling Filippo Valsorda — @FiloSo/le

Slide 2

Slide 2 text

What is fast?

Slide 3

Slide 3 text

A fast hash… … can hash many MB per second

Slide 4

Slide 4 text

A fast regex… … can process many MB/s

Slide 5

Slide 5 text

A fast database… … can store many GB per second

Slide 6

Slide 6 text

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

Slide 7

Slide 7 text

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

Slide 8

Slide 8 text

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

Slide 9

Slide 9 text

Fast is… Throughput and Latency

Slide 10

Slide 10 text

CPU proﬁling -cpuprofile   /debug/pprof/profile

Slide 11

Slide 11 text

SIGPROF CPU proﬁling

Slide 12

Slide 12 text

runtime/proc.go

Slide 13

Slide 13 text

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 proﬁling

Slide 14

Slide 14 text

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 proﬁling

Slide 15

Slide 15 text

I/O Observed latency h>p.Handler 1 CPU proﬁling

Slide 16

Slide 16 text

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

Slide 17

Slide 17 text

$ time curl http://127.0.0.1:12345/hash-and-write  9.831 total  go tool pprof -web slowserver cpu.pprof

Slide 18

Slide 18 text

No content

Slide 19

Slide 19 text

$ 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

Slide 20

Slide 20 text

Latency is not all about CPU

Slide 21

Slide 21 text

CPU proﬁling is for throughput The tracer is for latency

Slide 22

Slide 22 text

$ 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

Slide 23

Slide 23 text

No content

Slide 24

Slide 24 text

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

Slide 25

Slide 25 text

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

Slide 26

Slide 26 text

•Full event context •GorouOne metadata and history •Discrete events, not samples Trace vs. proﬁle

Slide 27

Slide 27 text

CPU proﬁling Total: 20 samples

Slide 28

Slide 28 text

Tracing events

Slide 29

Slide 29 text

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

Slide 30

Slide 30 text

No content

Slide 31

Slide 31 text

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

Slide 32

Slide 32 text

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

Slide 33

Slide 33 text

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

Slide 34

Slide 34 text

No content

Slide 35

Slide 35 text

No content

Slide 36

Slide 36 text

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

Slide 37

Slide 37 text

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

Slide 38

Slide 38 text

-pprof=sync

Slide 39

Slide 39 text

-pprof=sync

Slide 40

Slide 40 text

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

Slide 41

Slide 41 text

-pprof=net

Slide 42

Slide 42 text

-pprof=net

Slide 43

Slide 43 text

-pprof=net

Slide 44

Slide 44 text

No content

Slide 45

Slide 45 text

WriIng our own proﬁle 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)

Slide 46

Slide 46 text

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

Slide 47

Slide 47 text

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

Slide 48

Slide 48 text

No content

Slide 49

Slide 49 text

No content

Slide 50

Slide 50 text

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

Slide 51

Slide 51 text

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