You, latency and profiling @ GopherCon India 2017

Slide 1

Slide 1 text

You, latency and proﬁling Filippo Valsorda — @FiloSottile

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 milliseconds

Slide 7

Slide 7 text

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

Slide 8

Slide 8 text

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

CPU proﬁling SIGPROF

Slide 12

Slide 12 text

runtime/proc.go

Slide 13

Slide 13 text

CPU proﬁling http.Handler 1 Running on CPU http.Handler 2 I/O I/O http.Handler 3 I/O http.Handler 4 I/O

Slide 14

Slide 14 text

CPU proﬁling Running on CPU I/O I/O I/O I/O http.Handler 1 http.Handler 2 http.Handler 3 http.Handler 4

Slide 15

Slide 15 text

CPU proﬁling I/O Observed latency http.Handler 1

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

Slide 25

Slide 25 text

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

Slide 26

Slide 26 text

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

Slide 27

Slide 27 text

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

Slide 28

Slide 28 text

No content

Slide 29

Slide 29 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 30

Slide 30 text

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

Slide 31

Slide 31 text

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

Slide 32

Slide 32 text

No content

Slide 33

Slide 33 text

No content

Slide 34

Slide 34 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 35

Slide 35 text

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

Slide 36

Slide 36 text

-pprof=sync

Slide 37

Slide 37 text

-pprof=sync

Slide 38

Slide 38 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 39

Slide 39 text

-pprof=net

Slide 40

Slide 40 text

-pprof=net

Slide 41

Slide 41 text

No content

Slide 42

Slide 42 text

Writing 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 43

Slide 43 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 44

Slide 44 text

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

Slide 45

Slide 45 text

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

Slide 46

Slide 46 text

No content

Slide 47

Slide 47 text

No content

Slide 48

Slide 48 text

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

Slide 49

Slide 49 text

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