From 72d433c1ea15248303bc5a359deee59d1858c20c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Felix=20Geisend=C3=B6rfer?= Date: Sat, 9 Jan 2021 16:12:23 +0100 Subject: [PATCH] Initial pprof format notes --- examples/cpu/go.mod | 5 + examples/cpu/go.sum | 2 + examples/cpu/main.go | 52 ++ examples/cpu/pprof.samples.cpu.001.pb.gz | Bin 0 -> 1298 bytes examples/cpu/pprof.samples.cpu.001.pprof.txt | 47 ++ examples/cpu/pprof.samples.cpu.001.protoc.txt | 564 ++++++++++++++++++ pprof.md | 133 +++++ profile.proto | 212 +++++++ 8 files changed, 1015 insertions(+) create mode 100644 examples/cpu/go.mod create mode 100644 examples/cpu/go.sum create mode 100644 examples/cpu/main.go create mode 100644 examples/cpu/pprof.samples.cpu.001.pb.gz create mode 100644 examples/cpu/pprof.samples.cpu.001.pprof.txt create mode 100644 examples/cpu/pprof.samples.cpu.001.protoc.txt create mode 100644 pprof.md create mode 100644 profile.proto diff --git a/examples/cpu/go.mod b/examples/cpu/go.mod new file mode 100644 index 0000000..4c27b27 --- /dev/null +++ b/examples/cpu/go.mod @@ -0,0 +1,5 @@ +module github.com/felixge/go-profiler-notes/examples/cpu + +go 1.15 + +require golang.org/x/sync v0.0.0-20201207232520-09787c993a3a diff --git a/examples/cpu/go.sum b/examples/cpu/go.sum new file mode 100644 index 0000000..5f7eb37 --- /dev/null +++ b/examples/cpu/go.sum @@ -0,0 +1,2 @@ +golang.org/x/sync v0.0.0-20201207232520-09787c993a3a h1:DcqTD9SDLc+1P/r1EmRBwnVsrOwW+kk2vWf9n+1sGhs= +golang.org/x/sync v0.0.0-20201207232520-09787c993a3a/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= diff --git a/examples/cpu/main.go b/examples/cpu/main.go new file mode 100644 index 0000000..f0bb8c7 --- /dev/null +++ b/examples/cpu/main.go @@ -0,0 +1,52 @@ +package main + +import ( + "context" + "fmt" + "log" + "net/http" + _ "net/http/pprof" + "os" + "time" + + "golang.org/x/sync/errgroup" +) + +func main() { + if err := run(); err != nil { + fmt.Fprintln(os.Stderr, err) + os.Exit(1) + } +} + +func run() error { + g, _ := errgroup.WithContext(context.Background()) + + g.Go(func() error { + addr := "localhost:6060" + log.Printf("Listening on %s", addr) + return http.ListenAndServe(addr, nil) + }) + + g.Go(func() error { return computeSum(1000000, 10*time.Millisecond) }) + + return g.Wait() +} + +func computeSum(to int, sleep time.Duration) error { + for { + var sum int64 + for i := 0; i < to; i++ { + sum += int64(i) / 2 + sum += int64(i) / 3 + sum += int64(i) / 4 + sum += int64(i) / 5 + sum += int64(i) / 6 + sum += int64(i) / 7 + sum += int64(i) / 8 + } + time.Sleep(sleep) + } + + return nil +} diff --git a/examples/cpu/pprof.samples.cpu.001.pb.gz b/examples/cpu/pprof.samples.cpu.001.pb.gz new file mode 100644 index 0000000000000000000000000000000000000000..993d929518cd60e433e4876c734ac1fea31ded4f GIT binary patch literal 1298 zcmV+t1?~DDiwFP!00000|D0A!j1*ND=JsRyboWg6>Gz!n&=l|HpRS(E55wgD6(5P{ z#*m;3anTmlcX~QqRky5%47)KBS*SdM3W>zT5Q7U;FrWbqaREEyLK783j2Jh@6>cP& zfVsD4x+NNuaZ~l(FXw#cJLlZRO~rsQ=% zT=@9h8Yw(FHa>w-TsU+lGZq7~gJ@YGNa)?~ZX`8nX`_~f2on0sO+`d-wU&h_5_Wg&)yetP;8XfcRkLd!xN3B9wVv0g(MLPAfz^g3v9h~t}4Eei=G^z7+ZWX=%o z)DQp(eeshQWJm%p5)C1Vg#LKrh-3f{W;KKq5_;w3qmoJD#e#;AMnXS)TQMp8y{I7! zBcazXC?<^`lr@AAB=pNmiW$bwC6hryFJE~>G9!2;q9J6F&|mMqCYcPLifCm(B=q2W zN2S3m7PL4ZUMpz`IVAL_-;VS=+{$SPc_j44Ii;V&(^9{Hgnn~Jspau-L@Pm2_HshC zTfkLX42t-ahEPI6KRT&WOL$#2RF?8*)TGMzeN?MJ1qr=+STPkm7SrND@tT|uMM9rH zzgYLAtUHQ?9_`f~#Y3{MF*)W-$0Rd`7uIPA<4EY4^UD7?zM9k!CXmo;?<-~kZ$S-! zV4TLQLp6X1CTK#TC<29QvIY>t6irprHGnt{)8Xn!4PXc}G*ivi01}84tGOBgV4miy zg&IH-i?pav3QM%4P#Vj$tk5u4XhoqBq?A@iYXBJ>qhm@ri{o^>I#B~aTuE1|xE!vc zs}#!PYPwp*6|hRHDz1oY=$fil11RBIx>m)NaUES(U0(yJ;0C%uA&ML6MukRk6Wyd# z#&9#;tTM*2Mr#U9;1;^2T3{4HQkV<9m5emH-*#kS=Kf>PTdr? z8wPw&XtSsFCw=bu`Yg9P^Yu3G_}pm;?#*&fZwuY`OugL+=E8k4sTbAedRt7oo|x@e z+?#Ynz2OLx9p4aw7=+-yY zcFF(d`YxfOrYi_r#+oGlaMe~8@8udoKG07UNF~u6wY%ANw8k3Eg=^fMN%*<9} ztI;nzsNWW>=!H(uv3cE)GP^y_Z8u;$_0acpOPGeGKg=!5P}QgEQ`_p>b*r-DjgqvTiWvaii6gt7z^wIsvL4KN!m^Hf6 z`JfAPj+@;lIyU!wmg(Ou!|OKf!Fj*e3Ha2YOLZQM(cytBEbAeU8(sF`a-A(^H@nY< zJXGdN{W?aMKhA^Q!m_wGn1U@@^6xGG1}rX)<(H&9?(?80R=S6KM0k7DmF*89^zS|U z2Yg#NEZcYG2Zk3+4FY<^qwkz}>x;`5j-M^>zH|KcSLwa#-Sdomy0|O;2mk>8|Fz@1 IkP8U_01TgehyVZp literal 0 HcmV?d00001 diff --git a/examples/cpu/pprof.samples.cpu.001.pprof.txt b/examples/cpu/pprof.samples.cpu.001.pprof.txt new file mode 100644 index 0000000..beada8e --- /dev/null +++ b/examples/cpu/pprof.samples.cpu.001.pprof.txt @@ -0,0 +1,47 @@ +PeriodType: cpu nanoseconds +Period: 10000000 +Time: 2021-01-08 17:10:32.116825 +0100 CET +Duration: 3.13 +Samples: +samples/count cpu/nanoseconds + 19 190000000: 1 2 3 + 5 50000000: 4 5 2 3 + 1 10000000: 6 7 8 9 10 11 12 13 14 + 1 10000000: 15 16 17 11 18 14 + 2 20000000: 6 7 8 9 10 11 18 14 + 7 70000000: 19 20 21 22 23 24 14 + 3 30000000: 25 26 27 28 +Locations + 1: 0x1372f7f M=1 main.computeSum /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/cpu/main.go:39 s=0 + 2: 0x13730f2 M=1 main.run.func2 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/cpu/main.go:31 s=0 + 3: 0x1372cf8 M=1 golang.org/x/sync/errgroup.(*Group).Go.func1 /Users/felix.geisendoerfer/go/pkg/mod/golang.org/x/sync@v0.0.0-20201207232520-09787c993a3a/errgroup/errgroup.go:57 s=0 + 4: 0x10711c0 M=1 runtime.asyncPreempt /usr/local/Cellar/go/1.15.6/libexec/src/runtime/preempt_amd64.s:7 s=0 + 5: 0x1372f7e M=1 main.computeSum /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/cpu/main.go:37 s=0 + 6: 0x1058598 M=1 runtime.pthread_cond_wait /usr/local/Cellar/go/1.15.6/libexec/src/runtime/sys_darwin.go:414 s=0 + 7: 0x10351ac M=1 runtime.semasleep /usr/local/Cellar/go/1.15.6/libexec/src/runtime/os_darwin.go:63 s=0 + 8: 0x100de06 M=1 runtime.notesleep /usr/local/Cellar/go/1.15.6/libexec/src/runtime/lock_sema.go:181 s=0 + 9: 0x103ee64 M=1 runtime.stopm /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:1924 s=0 + 10: 0x104063e M=1 runtime.findrunnable /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:2485 s=0 + 11: 0x10412b6 M=1 runtime.schedule /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:2683 s=0 + 12: 0x1041a59 M=1 runtime.goschedImpl /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:2866 s=0 + 13: 0x1041cd3 M=1 runtime.gopreempt_m /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:2894 s=0 + 14: 0x106df3a M=1 runtime.mcall /usr/local/Cellar/go/1.15.6/libexec/src/runtime/asm_amd64.s:318 s=0 + 15: 0x1057ff7 M=1 runtime.nanotime1 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/sys_darwin.go:284 s=0 + 16: 0x1041704 M=1 runtime.nanotime /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time_nofake.go:19 s=0 + runtime.checkTimers /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:2757 s=0 + 17: 0x103fd69 M=1 runtime.findrunnable /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:2289 s=0 + 18: 0x104185c M=1 runtime.park_m /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:2851 s=0 + 19: 0x1057f58 M=1 runtime.write1 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/sys_darwin.go:270 s=0 + 20: 0x1034be4 M=1 runtime.write /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time_nofake.go:30 s=0 + runtime.netpollBreak /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll_kqueue.go:89 s=0 + 21: 0x1040c37 M=1 runtime.wakeNetPoller /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:2521 s=0 + 22: 0x10593e9 M=1 runtime.modtimer /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:480 s=0 + 23: 0x1058744 M=1 runtime.resettimer /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:529 s=0 + runtime.resetForSleep /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:197 s=0 + 24: 0x1041881 M=1 runtime.park_m /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:2840 s=0 + 25: 0x1057f10 M=1 runtime.usleep /usr/local/Cellar/go/1.15.6/libexec/src/runtime/sys_darwin.go:263 s=0 + 26: 0x1045cac M=1 runtime.sysmon /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:4660 s=0 + 27: 0x103d8a7 M=1 runtime.mstart1 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:1172 s=0 + 28: 0x103d7c5 M=1 runtime.mstart /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:1137 s=0 +Mappings +1: 0x0/0x0/0x0 [FN] diff --git a/examples/cpu/pprof.samples.cpu.001.protoc.txt b/examples/cpu/pprof.samples.cpu.001.protoc.txt new file mode 100644 index 0000000..a29a210 --- /dev/null +++ b/examples/cpu/pprof.samples.cpu.001.protoc.txt @@ -0,0 +1,564 @@ +sample_type { + type: 1 + unit: 2 +} +sample_type { + type: 3 + unit: 4 +} +sample { + location_id: 1 + location_id: 2 + location_id: 3 + value: 19 + value: 190000000 +} +sample { + location_id: 4 + location_id: 5 + location_id: 2 + location_id: 3 + value: 5 + value: 50000000 +} +sample { + location_id: 6 + location_id: 7 + location_id: 8 + location_id: 9 + location_id: 10 + location_id: 11 + location_id: 12 + location_id: 13 + location_id: 14 + value: 1 + value: 10000000 +} +sample { + location_id: 15 + location_id: 16 + location_id: 17 + location_id: 11 + location_id: 18 + location_id: 14 + value: 1 + value: 10000000 +} +sample { + location_id: 6 + location_id: 7 + location_id: 8 + location_id: 9 + location_id: 10 + location_id: 11 + location_id: 18 + location_id: 14 + value: 2 + value: 20000000 +} +sample { + location_id: 19 + location_id: 20 + location_id: 21 + location_id: 22 + location_id: 23 + location_id: 24 + location_id: 14 + value: 7 + value: 70000000 +} +sample { + location_id: 25 + location_id: 26 + location_id: 27 + location_id: 28 + value: 3 + value: 30000000 +} +mapping { + id: 1 + has_functions: true +} +location { + id: 1 + mapping_id: 1 + address: 20393855 + line { + function_id: 1 + line: 39 + } +} +location { + id: 2 + mapping_id: 1 + address: 20394226 + line { + function_id: 2 + line: 31 + } +} +location { + id: 3 + mapping_id: 1 + address: 20393208 + line { + function_id: 3 + line: 57 + } +} +location { + id: 4 + mapping_id: 1 + address: 17240512 + line { + function_id: 4 + line: 7 + } +} +location { + id: 5 + mapping_id: 1 + address: 20393854 + line { + function_id: 1 + line: 37 + } +} +location { + id: 6 + mapping_id: 1 + address: 17139096 + line { + function_id: 5 + line: 414 + } +} +location { + id: 7 + mapping_id: 1 + address: 16994732 + line { + function_id: 6 + line: 63 + } +} +location { + id: 8 + mapping_id: 1 + address: 16834054 + line { + function_id: 7 + line: 181 + } +} +location { + id: 9 + mapping_id: 1 + address: 17034852 + line { + function_id: 8 + line: 1924 + } +} +location { + id: 10 + mapping_id: 1 + address: 17040958 + line { + function_id: 9 + line: 2485 + } +} +location { + id: 11 + mapping_id: 1 + address: 17044150 + line { + function_id: 10 + line: 2683 + } +} +location { + id: 12 + mapping_id: 1 + address: 17046105 + line { + function_id: 11 + line: 2866 + } +} +location { + id: 13 + mapping_id: 1 + address: 17046739 + line { + function_id: 12 + line: 2894 + } +} +location { + id: 14 + mapping_id: 1 + address: 17227578 + line { + function_id: 13 + line: 318 + } +} +location { + id: 15 + mapping_id: 1 + address: 17137655 + line { + function_id: 14 + line: 284 + } +} +location { + id: 16 + mapping_id: 1 + address: 17045252 + line { + function_id: 15 + line: 19 + } + line { + function_id: 16 + line: 2757 + } +} +location { + id: 17 + mapping_id: 1 + address: 17038697 + line { + function_id: 9 + line: 2289 + } +} +location { + id: 18 + mapping_id: 1 + address: 17045596 + line { + function_id: 17 + line: 2851 + } +} +location { + id: 19 + mapping_id: 1 + address: 17137496 + line { + function_id: 18 + line: 270 + } +} +location { + id: 20 + mapping_id: 1 + address: 16993252 + line { + function_id: 19 + line: 30 + } + line { + function_id: 20 + line: 89 + } +} +location { + id: 21 + mapping_id: 1 + address: 17042487 + line { + function_id: 21 + line: 2521 + } +} +location { + id: 22 + mapping_id: 1 + address: 17142761 + line { + function_id: 22 + line: 480 + } +} +location { + id: 23 + mapping_id: 1 + address: 17139524 + line { + function_id: 23 + line: 529 + } + line { + function_id: 24 + line: 197 + } +} +location { + id: 24 + mapping_id: 1 + address: 17045633 + line { + function_id: 17 + line: 2840 + } +} +location { + id: 25 + mapping_id: 1 + address: 17137424 + line { + function_id: 25 + line: 263 + } +} +location { + id: 26 + mapping_id: 1 + address: 17063084 + line { + function_id: 26 + line: 4660 + } +} +location { + id: 27 + mapping_id: 1 + address: 17029287 + line { + function_id: 27 + line: 1172 + } +} +location { + id: 28 + mapping_id: 1 + address: 17029061 + line { + function_id: 28 + line: 1137 + } +} +function { + id: 1 + name: 5 + system_name: 5 + filename: 6 +} +function { + id: 2 + name: 7 + system_name: 7 + filename: 6 +} +function { + id: 3 + name: 8 + system_name: 8 + filename: 9 +} +function { + id: 4 + name: 10 + system_name: 10 + filename: 11 +} +function { + id: 5 + name: 12 + system_name: 12 + filename: 13 +} +function { + id: 6 + name: 14 + system_name: 14 + filename: 15 +} +function { + id: 7 + name: 16 + system_name: 16 + filename: 17 +} +function { + id: 8 + name: 18 + system_name: 18 + filename: 19 +} +function { + id: 9 + name: 20 + system_name: 20 + filename: 19 +} +function { + id: 10 + name: 21 + system_name: 21 + filename: 19 +} +function { + id: 11 + name: 22 + system_name: 22 + filename: 19 +} +function { + id: 12 + name: 23 + system_name: 23 + filename: 19 +} +function { + id: 13 + name: 24 + system_name: 24 + filename: 25 +} +function { + id: 14 + name: 26 + system_name: 26 + filename: 13 +} +function { + id: 15 + name: 27 + system_name: 27 + filename: 28 +} +function { + id: 16 + name: 29 + system_name: 29 + filename: 19 +} +function { + id: 17 + name: 30 + system_name: 30 + filename: 19 +} +function { + id: 18 + name: 31 + system_name: 31 + filename: 13 +} +function { + id: 19 + name: 32 + system_name: 32 + filename: 28 +} +function { + id: 20 + name: 33 + system_name: 33 + filename: 34 +} +function { + id: 21 + name: 35 + system_name: 35 + filename: 19 +} +function { + id: 22 + name: 36 + system_name: 36 + filename: 37 +} +function { + id: 23 + name: 38 + system_name: 38 + filename: 37 +} +function { + id: 24 + name: 39 + system_name: 39 + filename: 37 +} +function { + id: 25 + name: 40 + system_name: 40 + filename: 13 +} +function { + id: 26 + name: 41 + system_name: 41 + filename: 19 +} +function { + id: 27 + name: 42 + system_name: 42 + filename: 19 +} +function { + id: 28 + name: 43 + system_name: 43 + filename: 19 +} +string_table: "" +string_table: "samples" +string_table: "count" +string_table: "cpu" +string_table: "nanoseconds" +string_table: "main.computeSum" +string_table: "/Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/cpu/main.go" +string_table: "main.run.func2" +string_table: "golang.org/x/sync/errgroup.(*Group).Go.func1" +string_table: "/Users/felix.geisendoerfer/go/pkg/mod/golang.org/x/sync@v0.0.0-20201207232520-09787c993a3a/errgroup/errgroup.go" +string_table: "runtime.asyncPreempt" +string_table: "/usr/local/Cellar/go/1.15.6/libexec/src/runtime/preempt_amd64.s" +string_table: "runtime.pthread_cond_wait" +string_table: "/usr/local/Cellar/go/1.15.6/libexec/src/runtime/sys_darwin.go" +string_table: "runtime.semasleep" +string_table: "/usr/local/Cellar/go/1.15.6/libexec/src/runtime/os_darwin.go" +string_table: "runtime.notesleep" +string_table: "/usr/local/Cellar/go/1.15.6/libexec/src/runtime/lock_sema.go" +string_table: "runtime.stopm" +string_table: "/usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go" +string_table: "runtime.findrunnable" +string_table: "runtime.schedule" +string_table: "runtime.goschedImpl" +string_table: "runtime.gopreempt_m" +string_table: "runtime.mcall" +string_table: "/usr/local/Cellar/go/1.15.6/libexec/src/runtime/asm_amd64.s" +string_table: "runtime.nanotime1" +string_table: "runtime.nanotime" +string_table: "/usr/local/Cellar/go/1.15.6/libexec/src/runtime/time_nofake.go" +string_table: "runtime.checkTimers" +string_table: "runtime.park_m" +string_table: "runtime.write1" +string_table: "runtime.write" +string_table: "runtime.netpollBreak" +string_table: "/usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll_kqueue.go" +string_table: "runtime.wakeNetPoller" +string_table: "runtime.modtimer" +string_table: "/usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go" +string_table: "runtime.resettimer" +string_table: "runtime.resetForSleep" +string_table: "runtime.usleep" +string_table: "runtime.sysmon" +string_table: "runtime.mstart1" +string_table: "runtime.mstart" +time_nanos: 1610122232116825000 +duration_nanos: 3135113726 +period_type { + type: 3 + unit: 4 +} +period: 10000000 diff --git a/pprof.md b/pprof.md new file mode 100644 index 0000000..297f7e3 --- /dev/null +++ b/pprof.md @@ -0,0 +1,133 @@ +# Go's pprof tool & format + +The various profilers built into Go are designed to work with the [pprof visualization tool](https://github.com/google/pprof). The upstream pprof tool is designed to work with C++, Java and Go programs, but it's recommended to access the tool via the `go tool pprof` version that's [bundled](https://github.com/golang/go/tree/master/src/cmd/pprof) with the Go core. It's largely the same except for a few tweaks. + +## pprof Format + +The pprof tool defines a [protocol buffer](https://developers.google.com/protocol-buffers) output format, which is described in great detail in this [README](https://github.com/google/pprof/blob/master/proto/README.md) as well as the [profile.proto](https://github.com/google/pprof/blob/master/proto/profile.proto) definition file itself. The format is used for all profiling in Go, and the protocol buffer data files themselves are always comressed using gzip. + +TODO: Give a better high level introduction + +## Decoding pprof Files + +### Using `go tool pprof` + +The easiest way to decode a pprof file and see its contents is to use `go tool pprof -raw`. The output is formatted for human readability, so arguabiliy it's not as `-raw` as the `protoc` output shown later on. + +Let's have a look at the [examples/cpu/pprof.samples.cpu.001.pb.gz](./examples/cpu/pprof.samples.cpu.001.pb.gz) CPU profile included in this repository: + +``` +$ go tool pprof -raw examples/cpu/pprof.samples.cpu.001.pb.gz + +PeriodType: cpu nanoseconds +Period: 10000000 +Time: 2021-01-08 17:10:32.116825 +0100 CET +Duration: 3.13 +Samples: +samples/count cpu/nanoseconds + 19 190000000: 1 2 3 + 5 50000000: 4 5 2 3 + 1 10000000: 6 7 8 9 10 11 12 13 14 + 1 10000000: 15 16 17 11 18 14 + 2 20000000: 6 7 8 9 10 11 18 14 + 7 70000000: 19 20 21 22 23 24 14 + 3 30000000: 25 26 27 28 +Locations + 1: 0x1372f7f M=1 main.computeSum /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/cpu/main.go:39 s=0 + 2: 0x13730f2 M=1 main.run.func2 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/cpu/main.go:31 s=0 + 3: 0x1372cf8 M=1 golang.org/x/sync/errgroup.(*Group).Go.func1 /Users/felix.geisendoerfer/go/pkg/mod/golang.org/x/sync@v0.0.0-20201207232520-09787c993a3a/errgroup/errgroup.go:57 s=0 + ... +Mappings +1: 0x0/0x0/0x0 [FN] +``` + +The output above is truncated, [examples/cpu/pprof.samples.cpu.001.pprof.txt](./examples/cpu/pprof.samples.cpu.001.pprof.txt) has the full version. + +### Using `protoc` + +For those interested in seeing data closer to the raw binary storage, we need the `protoc` protocol buffer compiler. On macOS you can use `brew install protobuf` to install it, for other platform take a look at the [README's install section](https://github.com/protocolbuffers/protobuf#protocol-compiler-installation). + +Now let's take a look at the same CPU profile from above: + +``` +$ gzcat examples/cpu/pprof.samples.cpu.001.pb.gz | \ + protoc --decode perftools.profiles.Profile ./profile.proto + +sample_type { + type: 1 + unit: 2 +} +sample_type { + type: 3 + unit: 4 +} +sample { + location_id: 1 + location_id: 2 + location_id: 3 + value: 19 + value: 190000000 +} +sample { + location_id: 4 + location_id: 5 + location_id: 2 + location_id: 3 + value: 5 + value: 50000000 +} +... +mapping { + id: 1 + has_functions: true +} +location { + id: 1 + mapping_id: 1 + address: 20393855 + line { + function_id: 1 + line: 39 + } +} +location { + id: 2 + mapping_id: 1 + address: 20394226 + line { + function_id: 2 + line: 31 + } +} +... +function { + id: 1 + name: 5 + system_name: 5 + filename: 6 +} +function { + id: 2 + name: 7 + system_name: 7 + filename: 6 +} +... +string_table: "" +string_table: "samples" +string_table: "count" +string_table: "cpu" +string_table: "nanoseconds" +string_table: "main.computeSum" +string_table: "/Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/cpu/main.go" +... +time_nanos: 1610122232116825000 +duration_nanos: 3135113726 +period_type { + type: 3 + unit: 4 +} +period: 10000000 +``` + +The output above is truncated also, [pprof.samples.cpu.001.protoc.txt](./examples/cpu/pprof.samples.cpu.001.protoc.txt) has the full version. \ No newline at end of file diff --git a/profile.proto b/profile.proto new file mode 100644 index 0000000..ce5b6d7 --- /dev/null +++ b/profile.proto @@ -0,0 +1,212 @@ +// Copyright 2016 Google Inc. All Rights Reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +// Profile is a common stacktrace profile format. +// +// Measurements represented with this format should follow the +// following conventions: +// +// - Consumers should treat unset optional fields as if they had been +// set with their default value. +// +// - When possible, measurements should be stored in "unsampled" form +// that is most useful to humans. There should be enough +// information present to determine the original sampled values. +// +// - On-disk, the serialized proto must be gzip-compressed. +// +// - The profile is represented as a set of samples, where each sample +// references a sequence of locations, and where each location belongs +// to a mapping. +// - There is a N->1 relationship from sample.location_id entries to +// locations. For every sample.location_id entry there must be a +// unique Location with that id. +// - There is an optional N->1 relationship from locations to +// mappings. For every nonzero Location.mapping_id there must be a +// unique Mapping with that id. + +syntax = "proto3"; + +package perftools.profiles; + +option java_package = "com.google.perftools.profiles"; +option java_outer_classname = "ProfileProto"; + +message Profile { + // A description of the samples associated with each Sample.value. + // For a cpu profile this might be: + // [["cpu","nanoseconds"]] or [["wall","seconds"]] or [["syscall","count"]] + // For a heap profile, this might be: + // [["allocations","count"], ["space","bytes"]], + // If one of the values represents the number of events represented + // by the sample, by convention it should be at index 0 and use + // sample_type.unit == "count". + repeated ValueType sample_type = 1; + // The set of samples recorded in this profile. + repeated Sample sample = 2; + // Mapping from address ranges to the image/binary/library mapped + // into that address range. mapping[0] will be the main binary. + repeated Mapping mapping = 3; + // Useful program location + repeated Location location = 4; + // Functions referenced by locations + repeated Function function = 5; + // A common table for strings referenced by various messages. + // string_table[0] must always be "". + repeated string string_table = 6; + // frames with Function.function_name fully matching the following + // regexp will be dropped from the samples, along with their successors. + int64 drop_frames = 7; // Index into string table. + // frames with Function.function_name fully matching the following + // regexp will be kept, even if it matches drop_functions. + int64 keep_frames = 8; // Index into string table. + + // The following fields are informational, do not affect + // interpretation of results. + + // Time of collection (UTC) represented as nanoseconds past the epoch. + int64 time_nanos = 9; + // Duration of the profile, if a duration makes sense. + int64 duration_nanos = 10; + // The kind of events between sampled ocurrences. + // e.g [ "cpu","cycles" ] or [ "heap","bytes" ] + ValueType period_type = 11; + // The number of events between sampled occurrences. + int64 period = 12; + // Freeform text associated to the profile. + repeated int64 comment = 13; // Indices into string table. + // Index into the string table of the type of the preferred sample + // value. If unset, clients should default to the last sample value. + int64 default_sample_type = 14; +} + +// ValueType describes the semantics and measurement units of a value. +message ValueType { + int64 type = 1; // Index into string table. + int64 unit = 2; // Index into string table. +} + +// Each Sample records values encountered in some program +// context. The program context is typically a stack trace, perhaps +// augmented with auxiliary information like the thread-id, some +// indicator of a higher level request being handled etc. +message Sample { + // The ids recorded here correspond to a Profile.location.id. + // The leaf is at location_id[0]. + repeated uint64 location_id = 1; + // The type and unit of each value is defined by the corresponding + // entry in Profile.sample_type. All samples must have the same + // number of values, the same as the length of Profile.sample_type. + // When aggregating multiple samples into a single sample, the + // result has a list of values that is the elemntwise sum of the + // lists of the originals. + repeated int64 value = 2; + // label includes additional context for this sample. It can include + // things like a thread id, allocation size, etc + repeated Label label = 3; +} + +message Label { + int64 key = 1; // Index into string table + + // At most one of the following must be present + int64 str = 2; // Index into string table + int64 num = 3; + + // Should only be present when num is present. + // Specifies the units of num. + // Use arbitrary string (for example, "requests") as a custom count unit. + // If no unit is specified, consumer may apply heuristic to deduce the unit. + // Consumers may also interpret units like "bytes" and "kilobytes" as memory + // units and units like "seconds" and "nanoseconds" as time units, + // and apply appropriate unit conversions to these. + int64 num_unit = 4; // Index into string table +} + +message Mapping { + // Unique nonzero id for the mapping. + uint64 id = 1; + // Address at which the binary (or DLL) is loaded into memory. + uint64 memory_start = 2; + // The limit of the address range occupied by this mapping. + uint64 memory_limit = 3; + // Offset in the binary that corresponds to the first mapped address. + uint64 file_offset = 4; + // The object this entry is loaded from. This can be a filename on + // disk for the main binary and shared libraries, or virtual + // abstractions like "[vdso]". + int64 filename = 5; // Index into string table + // A string that uniquely identifies a particular program version + // with high probability. E.g., for binaries generated by GNU tools, + // it could be the contents of the .note.gnu.build-id field. + int64 build_id = 6; // Index into string table + + // The following fields indicate the resolution of symbolic info. + bool has_functions = 7; + bool has_filenames = 8; + bool has_line_numbers = 9; + bool has_inline_frames = 10; +} + +// Describes function and line table debug information. +message Location { + // Unique nonzero id for the location. A profile could use + // instruction addresses or any integer sequence as ids. + uint64 id = 1; + // The id of the corresponding profile.Mapping for this location. + // It can be unset if the mapping is unknown or not applicable for + // this profile type. + uint64 mapping_id = 2; + // The instruction address for this location, if available. It + // should be within [Mapping.memory_start...Mapping.memory_limit] + // for the corresponding mapping. A non-leaf address may be in the + // middle of a call instruction. It is up to display tools to find + // the beginning of the instruction if necessary. + uint64 address = 3; + // Multiple line indicates this location has inlined functions, + // where the last entry represents the caller into which the + // preceding entries were inlined. + // + // E.g., if memcpy() is inlined into printf: + // line[0].function_name == "memcpy" + // line[1].function_name == "printf" + repeated Line line = 4; + // Provides an indication that multiple symbols map to this location's + // address, for example due to identical code folding by the linker. In that + // case the line information above represents one of the multiple + // symbols. This field must be recomputed when the symbolization state of the + // profile changes. + bool is_folded = 5; +} + +message Line { + // The id of the corresponding profile.Function for this line. + uint64 function_id = 1; + // Line number in source code. + int64 line = 2; +} + +message Function { + // Unique nonzero id for the function. + uint64 id = 1; + // Name of the function, in human-readable form if available. + int64 name = 2; // Index into string table + // Name of the function, as identified by the system. + // For instance, it can be a C++ mangled name. + int64 system_name = 3; // Index into string table + // Source file containing the function. + int64 filename = 4; // Index into string table + // Line number in source file. + int64 start_line = 5; +} \ No newline at end of file