diff --git a/examples/goroutine/1.net.http.pprof.goroutine.debug0.pb.gz b/examples/goroutine/1.net.http.pprof.goroutine.debug0.pb.gz new file mode 100644 index 0000000..ed6471a Binary files /dev/null and b/examples/goroutine/1.net.http.pprof.goroutine.debug0.pb.gz differ diff --git a/examples/goroutine/1.net.http.pprof.goroutine.debug1.txt b/examples/goroutine/1.net.http.pprof.goroutine.debug1.txt new file mode 100644 index 0000000..8464b99 --- /dev/null +++ b/examples/goroutine/1.net.http.pprof.goroutine.debug1.txt @@ -0,0 +1,77 @@ +goroutine profile: total 10 +2 @ 0x103b125 0x106cd1f 0x13ac44a 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x106cd1e time.Sleep+0xbe /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +# 0x13ac449 main.shortSleepLoop+0x29 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 + +1 @ 0x103b125 0x10083ef 0x100802b 0x13ac4ed 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x13ac4ec main.chanReceiveForever+0x4c /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:177 + +1 @ 0x103b125 0x103425b 0x106a1d5 0x10d8185 0x10d91c5 0x10d91a3 0x11b8a8f 0x11cb72e 0x12ff937 0x11707c5 0x117092f 0x13005e8 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x106a1d4 internal/poll.runtime_pollWait+0x54 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +# 0x10d8184 internal/poll.(*pollDesc).wait+0x44 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +# 0x10d91c4 internal/poll.(*pollDesc).waitRead+0x1a4 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +# 0x10d91a2 internal/poll.(*FD).Read+0x182 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:159 +# 0x11b8a8e net.(*netFD).Read+0x4e /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_posix.go:55 +# 0x11cb72d net.(*conn).Read+0x8d /usr/local/Cellar/go/1.15.6/libexec/src/net/net.go:182 +# 0x12ff936 net/http.(*persistConn).Read+0x76 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:1887 +# 0x11707c4 bufio.(*Reader).fill+0x104 /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:101 +# 0x117092e bufio.(*Reader).Peek+0x4e /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:139 +# 0x13005e7 net/http.(*persistConn).readLoop+0x1a7 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2040 + +1 @ 0x103b125 0x103425b 0x106a1d5 0x10d8185 0x10dad7c 0x10dad5e 0x11ba005 0x11d4052 0x11d2ee5 0x12e9de6 0x12e9b17 0x13acce6 0x13acc90 0x106fd81 +# 0x106a1d4 internal/poll.runtime_pollWait+0x54 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +# 0x10d8184 internal/poll.(*pollDesc).wait+0x44 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +# 0x10dad7b internal/poll.(*pollDesc).waitRead+0x1fb /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +# 0x10dad5d internal/poll.(*FD).Accept+0x1dd /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:394 +# 0x11ba004 net.(*netFD).accept+0x44 /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_unix.go:172 +# 0x11d4051 net.(*TCPListener).accept+0x31 /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock_posix.go:139 +# 0x11d2ee4 net.(*TCPListener).Accept+0x64 /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock.go:261 +# 0x12e9de5 net/http.(*Server).Serve+0x265 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2937 +# 0x12e9b16 net/http.(*Server).ListenAndServe+0xb6 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2866 +# 0x13acce5 net/http.ListenAndServe+0x125 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:3120 +# 0x13acc8f main.main.func1+0xcf /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:123 + +1 @ 0x103b125 0x104afcf 0x130223c 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x130223b net/http.(*persistConn).writeLoop+0x11b /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2340 + +1 @ 0x103b125 0x104afcf 0x1302f59 0x12f74a5 0x12dd435 0x129e853 0x129e23f 0x12a025f 0x129fbbe 0x129fbce 0x13abba5 0x13abb8a 0x13acafe 0x13abe67 0x13ac247 0x103ad29 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x1302f58 net/http.(*persistConn).roundTrip+0x778 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2565 +# 0x12f74a4 net/http.(*Transport).roundTrip+0xa64 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:582 +# 0x12dd434 net/http.(*Transport).RoundTrip+0x34 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/roundtrip.go:17 +# 0x129e852 net/http.send+0x452 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:252 +# 0x129e23e net/http.(*Client).send+0xfe /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:176 +# 0x12a025e net/http.(*Client).do+0x45e /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:718 +# 0x129fbbd net/http.(*Client).Do+0xbd /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:586 +# 0x129fbcd net/http.(*Client).Get+0xcd /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:475 +# 0x13abba4 net/http.Get+0x104 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:447 +# 0x13abb89 main.writeHttpProfile+0xe9 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:92 +# 0x13acafd main.glob..func7+0x3d /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:79 +# 0x13abe66 main.writeProfiles+0x186 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:106 +# 0x13ac246 main.main+0x2c6 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:142 +# 0x103ad28 runtime.main+0x208 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:204 + +1 @ 0x103b125 0x106cd1f 0x13ac48b 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x106cd1e time.Sleep+0xbe /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +# 0x13ac48a main.sleepLoop+0x2a /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:171 + +1 @ 0x1069e1d 0x139efc2 0x139ed85 0x139b952 0x13a9865 0x13ab145 0x12e6424 0x12e834d 0x12e9a23 0x12e522d 0x106fd81 +# 0x1069e1c runtime/pprof.runtime_goroutineProfileWithLabels+0x5c /usr/local/Cellar/go/1.15.6/libexec/src/runtime/mprof.go:716 +# 0x139efc1 runtime/pprof.writeRuntimeProfile+0xe1 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:724 +# 0x139ed84 runtime/pprof.writeGoroutine+0xa4 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:684 +# 0x139b951 runtime/pprof.(*Profile).WriteTo+0x3f1 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:331 +# 0x13a9864 net/http/pprof.handler.ServeHTTP+0x384 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/pprof/pprof.go:256 +# 0x13ab144 net/http/pprof.Index+0x944 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/pprof/pprof.go:367 +# 0x12e6423 net/http.HandlerFunc.ServeHTTP+0x43 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2042 +# 0x12e834c net/http.(*ServeMux).ServeHTTP+0x1ac /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2417 +# 0x12e9a22 net/http.serverHandler.ServeHTTP+0xa2 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2843 +# 0x12e522c net/http.(*conn).serve+0x8ac /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:1925 + +1 @ 0x12def61 0x106fd81 +# 0x12def60 net/http.(*connReader).backgroundRead+0x0 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:689 + diff --git a/examples/goroutine/1.net.http.pprof.goroutine.debug2.txt b/examples/goroutine/1.net.http.pprof.goroutine.debug2.txt new file mode 100644 index 0000000..e3498f3 --- /dev/null +++ b/examples/goroutine/1.net.http.pprof.goroutine.debug2.txt @@ -0,0 +1,153 @@ +goroutine 41 [running]: +runtime/pprof.writeGoroutineStacks(0x14e5f60, 0xc0001d6000, 0xc0001b6270, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:693 +0x9f +runtime/pprof.writeGoroutine(0x14e5f60, 0xc0001d6000, 0x2, 0x1714f40, 0xc0001ba420) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:682 +0x45 +runtime/pprof.(*Profile).WriteTo(0x17179e0, 0x14e5f60, 0xc0001d6000, 0x2, 0xc0001d6000, 0xc0003379d8) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:331 +0x3f2 +net/http/pprof.handler.ServeHTTP(0xc0001ca071, 0x9, 0x14ec9a0, 0xc0001d6000, 0xc000110300) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/pprof/pprof.go:256 +0x385 +net/http/pprof.Index(0x14ec9a0, 0xc0001d6000, 0xc000110300) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/pprof/pprof.go:367 +0x945 +net/http.HandlerFunc.ServeHTTP(0x1486d90, 0x14ec9a0, 0xc0001d6000, 0xc000110300) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2042 +0x44 +net/http.(*ServeMux).ServeHTTP(0x1725ba0, 0x14ec9a0, 0xc0001d6000, 0xc000110300) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2417 +0x1ad +net/http.serverHandler.ServeHTTP(0xc00019c000, 0x14ec9a0, 0xc0001d6000, 0xc000110300) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2843 +0xa3 +net/http.(*conn).serve(0xc0000c6320, 0x14ed4a0, 0xc000322000) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:1925 +0x8ad +created by net/http.(*Server).Serve + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2969 +0x36c + +goroutine 1 [select]: +net/http.(*persistConn).roundTrip(0xc0000cea20, 0xc0001b40c0, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2565 +0x779 +net/http.(*Transport).roundTrip(0x171d020, 0xc0001ce000, 0x30, 0x30, 0x180de98) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:582 +0xa65 +net/http.(*Transport).RoundTrip(0x171d020, 0xc0001ce000, 0x171d020, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/roundtrip.go:17 +0x35 +net/http.send(0xc0001ce000, 0x14e5d80, 0x171d020, 0x0, 0x0, 0x0, 0xc0001c8018, 0x203000, 0x1, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:252 +0x453 +net/http.(*Client).send(0x17259e0, 0xc0001ce000, 0x0, 0x0, 0x0, 0xc0001c8018, 0x0, 0x1, 0xf8) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:176 +0xff +net/http.(*Client).do(0x17259e0, 0xc0001ce000, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:718 +0x45f +net/http.(*Client).Do(...) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:586 +net/http.(*Client).Get(0x17259e0, 0xc0001cc000, 0x33, 0x2, 0x2, 0xc0001cc000) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:475 +0xbe +net/http.Get(...) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:447 +main.writeHttpProfile(0x14e5940, 0xc0001b6090, 0x2, 0x0, 0x0) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:92 +0x105 +main.glob..func8(0x14e5940, 0xc0001b6090, 0xc000213eb0, 0x2) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:85 +0x3e +main.writeProfiles(0x1, 0xc0000c4008, 0x146641d) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:106 +0x187 +main.main() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:142 +0x2c7 + +goroutine 22 [sleep]: +time.Sleep(0x3b9aca00) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.shortSleepLoop() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 +0x2a +created by main.indirectShortSleepLoop2 + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:185 +0x35 + +goroutine 3 [IO wait]: +internal/poll.runtime_pollWait(0x1e91e88, 0x72, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55 +internal/poll.(*pollDesc).wait(0xc00019e018, 0x72, 0x0, 0x0, 0x1465786) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45 +internal/poll.(*pollDesc).waitRead(...) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +internal/poll.(*FD).Accept(0xc00019e000, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:394 +0x1fc +net.(*netFD).accept(0xc00019e000, 0x7d667d63cbbded3e, 0x1789ccbbded3e, 0x100000001) + /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_unix.go:172 +0x45 +net.(*TCPListener).accept(0xc000188060, 0x60006709, 0xc000196da8, 0x109abe6) + /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock_posix.go:139 +0x32 +net.(*TCPListener).Accept(0xc000188060, 0xc000196df8, 0x18, 0xc000001200, 0x12e9eec) + /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock.go:261 +0x65 +net/http.(*Server).Serve(0xc00019c000, 0x14ec6e0, 0xc000188060, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2937 +0x266 +net/http.(*Server).ListenAndServe(0xc00019c000, 0xc00019c000, 0x1475536) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2866 +0xb7 +net/http.ListenAndServe(...) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:3120 +main.main.func1(0xc000032120) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:123 +0x126 +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:121 +0xc5 + +goroutine 4 [sleep]: +time.Sleep(0x3b9aca00) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.shortSleepLoop() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 +0x2a +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:130 +0x195 + +goroutine 5 [sleep]: +time.Sleep(0x34630b8a000) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.sleepLoop(0x34630b8a000) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:171 +0x2b +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:131 +0x1bc + +goroutine 6 [chan receive]: +main.chanReceiveForever() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:177 +0x4d +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:132 +0x1d4 + +goroutine 24 [select]: +net/http.(*persistConn).writeLoop(0xc0000cea20) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2340 +0x11c +created by net/http.(*Transport).dialConn + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:1709 +0xcdc + +goroutine 23 [IO wait]: +internal/poll.runtime_pollWait(0x1e91da0, 0x72, 0x14e6ca0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55 +internal/poll.(*pollDesc).wait(0xc00010e198, 0x72, 0x14e6c00, 0x16db878, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45 +internal/poll.(*pollDesc).waitRead(...) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +internal/poll.(*FD).Read(0xc00010e180, 0xc000256000, 0x1000, 0x1000, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:159 +0x1a5 +net.(*netFD).Read(0xc00010e180, 0xc000256000, 0x1000, 0x1000, 0x103b1dc, 0xc000199b58, 0x10680e0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_posix.go:55 +0x4f +net.(*conn).Read(0xc000010008, 0xc000256000, 0x1000, 0x1000, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/net.go:182 +0x8e +net/http.(*persistConn).Read(0xc0000cea20, 0xc000256000, 0x1000, 0x1000, 0xc00009e300, 0xc000199c58, 0x10074b5) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:1887 +0x77 +bufio.(*Reader).fill(0xc0001801e0) + /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:101 +0x105 +bufio.(*Reader).Peek(0xc0001801e0, 0x1, 0x0, 0x0, 0x1, 0x0, 0xc000030180) + /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:139 +0x4f +net/http.(*persistConn).readLoop(0xc0000cea20) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2040 +0x1a8 +created by net/http.(*Transport).dialConn + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:1708 +0xcb7 + +goroutine 67 [IO wait]: +internal/poll.runtime_pollWait(0x1e91cb8, 0x72, 0x14e6ca0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55 +internal/poll.(*pollDesc).wait(0xc00019e098, 0x72, 0x14e6c00, 0x16db878, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45 +internal/poll.(*pollDesc).waitRead(...) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +internal/poll.(*FD).Read(0xc00019e080, 0xc00007c311, 0x1, 0x1, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:159 +0x1a5 +net.(*netFD).Read(0xc00019e080, 0xc00007c311, 0x1, 0x1, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_posix.go:55 +0x4f +net.(*conn).Read(0xc000186028, 0xc00007c311, 0x1, 0x1, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/net.go:182 +0x8e +net/http.(*connReader).backgroundRead(0xc00007c300) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:690 +0x58 +created by net/http.(*connReader).startBackgroundRead + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:686 +0xd5 diff --git a/examples/goroutine/1.pprof.lookup.goroutine.debug0.pb.gz b/examples/goroutine/1.pprof.lookup.goroutine.debug0.pb.gz new file mode 100644 index 0000000..ab17639 Binary files /dev/null and b/examples/goroutine/1.pprof.lookup.goroutine.debug0.pb.gz differ diff --git a/examples/goroutine/1.pprof.lookup.goroutine.debug1.txt b/examples/goroutine/1.pprof.lookup.goroutine.debug1.txt new file mode 100644 index 0000000..10873b5 --- /dev/null +++ b/examples/goroutine/1.pprof.lookup.goroutine.debug1.txt @@ -0,0 +1,39 @@ +goroutine profile: total 6 +2 @ 0x103b125 0x106cd1f 0x13ac44a 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x106cd1e time.Sleep+0xbe /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +# 0x13ac449 main.shortSleepLoop+0x29 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 + +1 @ 0x103b125 0x10083ef 0x100802b 0x13ac4ed 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x13ac4ec main.chanReceiveForever+0x4c /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:177 + +1 @ 0x103b125 0x103425b 0x106a1d5 0x10d8185 0x10dad7c 0x10dad5e 0x11ba005 0x11d4052 0x11d2ee5 0x12e9de6 0x12e9b17 0x13acce6 0x13acc90 0x106fd81 +# 0x106a1d4 internal/poll.runtime_pollWait+0x54 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +# 0x10d8184 internal/poll.(*pollDesc).wait+0x44 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +# 0x10dad7b internal/poll.(*pollDesc).waitRead+0x1fb /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +# 0x10dad5d internal/poll.(*FD).Accept+0x1dd /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:394 +# 0x11ba004 net.(*netFD).accept+0x44 /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_unix.go:172 +# 0x11d4051 net.(*TCPListener).accept+0x31 /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock_posix.go:139 +# 0x11d2ee4 net.(*TCPListener).Accept+0x64 /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock.go:261 +# 0x12e9de5 net/http.(*Server).Serve+0x265 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2937 +# 0x12e9b16 net/http.(*Server).ListenAndServe+0xb6 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2866 +# 0x13acce5 net/http.ListenAndServe+0x125 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:3120 +# 0x13acc8f main.main.func1+0xcf /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:123 + +1 @ 0x103b125 0x106cd1f 0x13ac48b 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x106cd1e time.Sleep+0xbe /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +# 0x13ac48a main.sleepLoop+0x2a /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:171 + +1 @ 0x1069e1d 0x139efc2 0x139ed85 0x139b952 0x13ac965 0x13abe67 0x13ac247 0x103ad29 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x1069e1c runtime/pprof.runtime_goroutineProfileWithLabels+0x5c /usr/local/Cellar/go/1.15.6/libexec/src/runtime/mprof.go:716 +# 0x139efc1 runtime/pprof.writeRuntimeProfile+0xe1 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:724 +# 0x139ed84 runtime/pprof.writeGoroutine+0xa4 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:684 +# 0x139b951 runtime/pprof.(*Profile).WriteTo+0x3f1 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:331 +# 0x13ac964 main.glob..func4+0x64 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:60 +# 0x13abe66 main.writeProfiles+0x186 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:106 +# 0x13ac246 main.main+0x2c6 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:142 +# 0x103ad28 runtime.main+0x208 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:204 + diff --git a/examples/goroutine/1.pprof.lookup.goroutine.debug2.txt b/examples/goroutine/1.pprof.lookup.goroutine.debug2.txt new file mode 100644 index 0000000..a6e03e0 --- /dev/null +++ b/examples/goroutine/1.pprof.lookup.goroutine.debug2.txt @@ -0,0 +1,69 @@ +goroutine 1 [running]: +runtime/pprof.writeGoroutineStacks(0x14e5940, 0xc0000abb00, 0x101b8a5, 0xc000213d20) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:693 +0x9f +runtime/pprof.writeGoroutine(0x14e5940, 0xc0000abb00, 0x2, 0xc000213dc0, 0x10ee5c8) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:682 +0x45 +runtime/pprof.(*Profile).WriteTo(0x17179e0, 0x14e5940, 0xc0000abb00, 0x2, 0xc00002c210, 0xc0002041a0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:331 +0x3f2 +main.glob..func5(0x14e5940, 0xc0000abb00, 0xc000213eb0, 0x2) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:67 +0x65 +main.writeProfiles(0x1, 0xc0000c4008, 0x146641d) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:106 +0x187 +main.main() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:142 +0x2c7 + +goroutine 22 [sleep]: +time.Sleep(0x3b9aca00) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.shortSleepLoop() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 +0x2a +created by main.indirectShortSleepLoop2 + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:185 +0x35 + +goroutine 3 [IO wait]: +internal/poll.runtime_pollWait(0x1e91e88, 0x72, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55 +internal/poll.(*pollDesc).wait(0xc00019e018, 0x72, 0x0, 0x0, 0x1465786) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45 +internal/poll.(*pollDesc).waitRead(...) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +internal/poll.(*FD).Accept(0xc00019e000, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:394 +0x1fc +net.(*netFD).accept(0xc00019e000, 0xc0001822d0, 0x1010038, 0xc000088000) + /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_unix.go:172 +0x45 +net.(*TCPListener).accept(0xc000188060, 0xc000196da8, 0x1010038, 0x30) + /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock_posix.go:139 +0x32 +net.(*TCPListener).Accept(0xc000188060, 0x1436c40, 0xc0001822d0, 0x13f4620, 0x1714f50) + /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock.go:261 +0x65 +net/http.(*Server).Serve(0xc00019c000, 0x14ec6e0, 0xc000188060, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2937 +0x266 +net/http.(*Server).ListenAndServe(0xc00019c000, 0xc00019c000, 0x1475536) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2866 +0xb7 +net/http.ListenAndServe(...) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:3120 +main.main.func1(0xc000032120) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:123 +0x126 +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:121 +0xc5 + +goroutine 4 [sleep]: +time.Sleep(0x3b9aca00) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.shortSleepLoop() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 +0x2a +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:130 +0x195 + +goroutine 5 [sleep]: +time.Sleep(0x34630b8a000) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.sleepLoop(0x34630b8a000) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:171 +0x2b +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:131 +0x1bc + +goroutine 6 [chan receive]: +main.chanReceiveForever() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:177 +0x4d +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:132 +0x1d4 diff --git a/examples/goroutine/1.runtime.goroutineprofile.json b/examples/goroutine/1.runtime.goroutineprofile.json new file mode 100644 index 0000000..3161341 --- /dev/null +++ b/examples/goroutine/1.runtime.goroutineprofile.json @@ -0,0 +1,218 @@ +[ + { + "Stack0": [ + 20629256, + 20629212, + 20627047, + 20628039, + 17018153, + 17235329, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0 + ] + }, + { + "Stack0": [ + 17019173, + 17222943, + 20628554, + 17235329, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0 + ] + }, + { + "Stack0": [ + 17019173, + 16990811, + 17211861, + 17662341, + 17673596, + 17673566, + 18587653, + 18694226, + 18689765, + 19832294, + 19831575, + 20630758, + 20630672, + 17235329, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0 + ] + }, + { + "Stack0": [ + 17019173, + 17222943, + 20628554, + 17235329, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0 + ] + }, + { + "Stack0": [ + 17019173, + 17222943, + 20628619, + 17235329, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0 + ] + }, + { + "Stack0": [ + 17019173, + 16810991, + 16810027, + 20628717, + 17235329, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0 + ] + } +] diff --git a/examples/goroutine/1.runtime.stack.txt b/examples/goroutine/1.runtime.stack.txt new file mode 100644 index 0000000..e84af8c --- /dev/null +++ b/examples/goroutine/1.runtime.stack.txt @@ -0,0 +1,63 @@ +goroutine 1 [running]: +main.glob..func1(0x14e5940, 0xc0000aa7b0, 0xc000064eb0, 0x2) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:29 +0x6f +main.writeProfiles(0x1, 0xc0000c4008, 0x146641d) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:106 +0x187 +main.main() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:142 +0x2c7 + +goroutine 22 [sleep]: +time.Sleep(0x3b9aca00) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.shortSleepLoop() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 +0x2a +created by main.indirectShortSleepLoop2 + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:185 +0x35 + +goroutine 3 [IO wait]: +internal/poll.runtime_pollWait(0x1e91e88, 0x72, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55 +internal/poll.(*pollDesc).wait(0xc00019e018, 0x72, 0x0, 0x0, 0x1465786) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45 +internal/poll.(*pollDesc).waitRead(...) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +internal/poll.(*FD).Accept(0xc00019e000, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:394 +0x1fc +net.(*netFD).accept(0xc00019e000, 0xc0001822d0, 0x1010038, 0xc000088000) + /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_unix.go:172 +0x45 +net.(*TCPListener).accept(0xc000188060, 0xc000196da8, 0x1010038, 0x30) + /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock_posix.go:139 +0x32 +net.(*TCPListener).Accept(0xc000188060, 0x1436c40, 0xc0001822d0, 0x13f4620, 0x1714f50) + /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock.go:261 +0x65 +net/http.(*Server).Serve(0xc00019c000, 0x14ec6e0, 0xc000188060, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2937 +0x266 +net/http.(*Server).ListenAndServe(0xc00019c000, 0xc00019c000, 0x1475536) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2866 +0xb7 +net/http.ListenAndServe(...) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:3120 +main.main.func1(0xc000032120) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:123 +0x126 +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:121 +0xc5 + +goroutine 4 [sleep]: +time.Sleep(0x3b9aca00) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.shortSleepLoop() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 +0x2a +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:130 +0x195 + +goroutine 5 [sleep]: +time.Sleep(0x34630b8a000) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.sleepLoop(0x34630b8a000) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:171 +0x2b +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:131 +0x1bc + +goroutine 6 [chan receive]: +main.chanReceiveForever() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:177 +0x4d +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:132 +0x1d4 diff --git a/examples/goroutine/2.net.http.pprof.goroutine.debug0.pb.gz b/examples/goroutine/2.net.http.pprof.goroutine.debug0.pb.gz new file mode 100644 index 0000000..79da14a Binary files /dev/null and b/examples/goroutine/2.net.http.pprof.goroutine.debug0.pb.gz differ diff --git a/examples/goroutine/2.net.http.pprof.goroutine.debug1.txt b/examples/goroutine/2.net.http.pprof.goroutine.debug1.txt new file mode 100644 index 0000000..27d4b98 --- /dev/null +++ b/examples/goroutine/2.net.http.pprof.goroutine.debug1.txt @@ -0,0 +1,77 @@ +goroutine profile: total 10 +2 @ 0x103b125 0x106cd1f 0x13ac44a 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x106cd1e time.Sleep+0xbe /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +# 0x13ac449 main.shortSleepLoop+0x29 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 + +1 @ 0x103b125 0x10083ef 0x100802b 0x13ac4ed 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x13ac4ec main.chanReceiveForever+0x4c /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:177 + +1 @ 0x103b125 0x103425b 0x106a1d5 0x10d8185 0x10d91c5 0x10d91a3 0x11b8a8f 0x11cb72e 0x12ff937 0x11707c5 0x117092f 0x13005e8 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x106a1d4 internal/poll.runtime_pollWait+0x54 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +# 0x10d8184 internal/poll.(*pollDesc).wait+0x44 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +# 0x10d91c4 internal/poll.(*pollDesc).waitRead+0x1a4 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +# 0x10d91a2 internal/poll.(*FD).Read+0x182 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:159 +# 0x11b8a8e net.(*netFD).Read+0x4e /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_posix.go:55 +# 0x11cb72d net.(*conn).Read+0x8d /usr/local/Cellar/go/1.15.6/libexec/src/net/net.go:182 +# 0x12ff936 net/http.(*persistConn).Read+0x76 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:1887 +# 0x11707c4 bufio.(*Reader).fill+0x104 /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:101 +# 0x117092e bufio.(*Reader).Peek+0x4e /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:139 +# 0x13005e7 net/http.(*persistConn).readLoop+0x1a7 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2040 + +1 @ 0x103b125 0x103425b 0x106a1d5 0x10d8185 0x10dad7c 0x10dad5e 0x11ba005 0x11d4052 0x11d2ee5 0x12e9de6 0x12e9b17 0x13acce6 0x13acc90 0x106fd81 +# 0x106a1d4 internal/poll.runtime_pollWait+0x54 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +# 0x10d8184 internal/poll.(*pollDesc).wait+0x44 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +# 0x10dad7b internal/poll.(*pollDesc).waitRead+0x1fb /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +# 0x10dad5d internal/poll.(*FD).Accept+0x1dd /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:394 +# 0x11ba004 net.(*netFD).accept+0x44 /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_unix.go:172 +# 0x11d4051 net.(*TCPListener).accept+0x31 /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock_posix.go:139 +# 0x11d2ee4 net.(*TCPListener).Accept+0x64 /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock.go:261 +# 0x12e9de5 net/http.(*Server).Serve+0x265 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2937 +# 0x12e9b16 net/http.(*Server).ListenAndServe+0xb6 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2866 +# 0x13acce5 net/http.ListenAndServe+0x125 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:3120 +# 0x13acc8f main.main.func1+0xcf /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:123 + +1 @ 0x103b125 0x104afcf 0x130223c 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x130223b net/http.(*persistConn).writeLoop+0x11b /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2340 + +1 @ 0x103b125 0x104afcf 0x1302f59 0x12f74a5 0x12dd435 0x129e853 0x129e23f 0x12a025f 0x129fbbe 0x129fbce 0x13abba5 0x13abb8a 0x13acafe 0x13abe67 0x13ac352 0x103ad29 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x1302f58 net/http.(*persistConn).roundTrip+0x778 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2565 +# 0x12f74a4 net/http.(*Transport).roundTrip+0xa64 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:582 +# 0x12dd434 net/http.(*Transport).RoundTrip+0x34 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/roundtrip.go:17 +# 0x129e852 net/http.send+0x452 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:252 +# 0x129e23e net/http.(*Client).send+0xfe /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:176 +# 0x12a025e net/http.(*Client).do+0x45e /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:718 +# 0x129fbbd net/http.(*Client).Do+0xbd /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:586 +# 0x129fbcd net/http.(*Client).Get+0xcd /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:475 +# 0x13abba4 net/http.Get+0x104 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:447 +# 0x13abb89 main.writeHttpProfile+0xe9 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:92 +# 0x13acafd main.glob..func7+0x3d /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:79 +# 0x13abe66 main.writeProfiles+0x186 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:106 +# 0x13ac351 main.main+0x3d1 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:152 +# 0x103ad28 runtime.main+0x208 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:204 + +1 @ 0x103b125 0x106cd1f 0x13ac48b 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x106cd1e time.Sleep+0xbe /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +# 0x13ac48a main.sleepLoop+0x2a /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:171 + +1 @ 0x1069e1d 0x139efc2 0x139ed85 0x139b952 0x13a9865 0x13ab145 0x12e6424 0x12e834d 0x12e9a23 0x12e522d 0x106fd81 +# 0x1069e1c runtime/pprof.runtime_goroutineProfileWithLabels+0x5c /usr/local/Cellar/go/1.15.6/libexec/src/runtime/mprof.go:716 +# 0x139efc1 runtime/pprof.writeRuntimeProfile+0xe1 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:724 +# 0x139ed84 runtime/pprof.writeGoroutine+0xa4 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:684 +# 0x139b951 runtime/pprof.(*Profile).WriteTo+0x3f1 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:331 +# 0x13a9864 net/http/pprof.handler.ServeHTTP+0x384 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/pprof/pprof.go:256 +# 0x13ab144 net/http/pprof.Index+0x944 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/pprof/pprof.go:367 +# 0x12e6423 net/http.HandlerFunc.ServeHTTP+0x43 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2042 +# 0x12e834c net/http.(*ServeMux).ServeHTTP+0x1ac /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2417 +# 0x12e9a22 net/http.serverHandler.ServeHTTP+0xa2 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2843 +# 0x12e522c net/http.(*conn).serve+0x8ac /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:1925 + +1 @ 0x12def61 0x106fd81 +# 0x12def60 net/http.(*connReader).backgroundRead+0x0 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:689 + diff --git a/examples/goroutine/2.net.http.pprof.goroutine.debug2.txt b/examples/goroutine/2.net.http.pprof.goroutine.debug2.txt new file mode 100644 index 0000000..f4fcd12 --- /dev/null +++ b/examples/goroutine/2.net.http.pprof.goroutine.debug2.txt @@ -0,0 +1,153 @@ +goroutine 41 [running]: +runtime/pprof.writeGoroutineStacks(0x14e5f60, 0xc0002ae000, 0xc0002a20c0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:693 +0x9f +runtime/pprof.writeGoroutine(0x14e5f60, 0xc0002ae000, 0x2, 0x1714f40, 0xc0002a4160) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:682 +0x45 +runtime/pprof.(*Profile).WriteTo(0x17179e0, 0x14e5f60, 0xc0002ae000, 0x2, 0xc0002ae000, 0xc0003379d8) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:331 +0x3f2 +net/http/pprof.handler.ServeHTTP(0xc00029e011, 0x9, 0x14ec9a0, 0xc0002ae000, 0xc0001da100) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/pprof/pprof.go:256 +0x385 +net/http/pprof.Index(0x14ec9a0, 0xc0002ae000, 0xc0001da100) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/pprof/pprof.go:367 +0x945 +net/http.HandlerFunc.ServeHTTP(0x1486d90, 0x14ec9a0, 0xc0002ae000, 0xc0001da100) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2042 +0x44 +net/http.(*ServeMux).ServeHTTP(0x1725ba0, 0x14ec9a0, 0xc0002ae000, 0xc0001da100) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2417 +0x1ad +net/http.serverHandler.ServeHTTP(0xc00019c000, 0x14ec9a0, 0xc0002ae000, 0xc0001da100) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2843 +0xa3 +net/http.(*conn).serve(0xc0000c6320, 0x14ed4a0, 0xc000322000) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:1925 +0x8ad +created by net/http.(*Server).Serve + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2969 +0x36c + +goroutine 1 [select]: +net/http.(*persistConn).roundTrip(0xc0000cea20, 0xc000322240, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2565 +0x779 +net/http.(*Transport).roundTrip(0x171d020, 0xc0001da200, 0x30, 0x30, 0x180d7d0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:582 +0xa65 +net/http.(*Transport).RoundTrip(0x171d020, 0xc0001da200, 0x171d020, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/roundtrip.go:17 +0x35 +net/http.send(0xc0001da200, 0x14e5d80, 0x171d020, 0x0, 0x0, 0x0, 0xc000186040, 0x203000, 0x1, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:252 +0x453 +net/http.(*Client).send(0x17259e0, 0xc0001da200, 0x0, 0x0, 0x0, 0xc000186040, 0x0, 0x1, 0xf8) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:176 +0xff +net/http.(*Client).do(0x17259e0, 0xc0001da200, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:718 +0x45f +net/http.(*Client).Do(...) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:586 +net/http.(*Client).Get(0x17259e0, 0xc0001ce080, 0x33, 0x2, 0x2, 0xc0001ce080) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:475 +0xbe +net/http.Get(...) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/client.go:447 +main.writeHttpProfile(0x14e5940, 0xc00007c630, 0x2, 0x0, 0x0) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:92 +0x105 +main.glob..func8(0x14e5940, 0xc00007c630, 0xc000333eb0, 0x2) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:85 +0x3e +main.writeProfiles(0x2, 0xc0000c4008, 0x1466424) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:106 +0x187 +main.main() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:152 +0x3d2 + +goroutine 22 [sleep, 1 minutes]: +time.Sleep(0x3b9aca00) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.shortSleepLoop() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 +0x2a +created by main.indirectShortSleepLoop2 + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:185 +0x35 + +goroutine 3 [IO wait, 1 minutes]: +internal/poll.runtime_pollWait(0x1e91e88, 0x72, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55 +internal/poll.(*pollDesc).wait(0xc00019e018, 0x72, 0x0, 0x0, 0x1465786) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45 +internal/poll.(*pollDesc).waitRead(...) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +internal/poll.(*FD).Accept(0xc00019e000, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:394 +0x1fc +net.(*netFD).accept(0xc00019e000, 0x7d667d63cbbded3e, 0x1789ccbbded3e, 0x100000001) + /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_unix.go:172 +0x45 +net.(*TCPListener).accept(0xc000188060, 0x60006709, 0xc000196da8, 0x109abe6) + /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock_posix.go:139 +0x32 +net.(*TCPListener).Accept(0xc000188060, 0xc000196df8, 0x18, 0xc000001200, 0x12e9eec) + /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock.go:261 +0x65 +net/http.(*Server).Serve(0xc00019c000, 0x14ec6e0, 0xc000188060, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2937 +0x266 +net/http.(*Server).ListenAndServe(0xc00019c000, 0xc00019c000, 0x1475536) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2866 +0xb7 +net/http.ListenAndServe(...) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:3120 +main.main.func1(0xc000032120) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:123 +0x126 +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:121 +0xc5 + +goroutine 4 [sleep, 1 minutes]: +time.Sleep(0x3b9aca00) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.shortSleepLoop() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 +0x2a +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:130 +0x195 + +goroutine 5 [sleep, 1 minutes]: +time.Sleep(0x34630b8a000) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.sleepLoop(0x34630b8a000) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:171 +0x2b +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:131 +0x1bc + +goroutine 6 [chan receive, 1 minutes]: +main.chanReceiveForever() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:177 +0x4d +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:132 +0x1d4 + +goroutine 24 [select]: +net/http.(*persistConn).writeLoop(0xc0000cea20) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2340 +0x11c +created by net/http.(*Transport).dialConn + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:1709 +0xcdc + +goroutine 23 [IO wait]: +internal/poll.runtime_pollWait(0x1e91da0, 0x72, 0x14e6ca0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55 +internal/poll.(*pollDesc).wait(0xc00010e198, 0x72, 0x14e6c00, 0x16db878, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45 +internal/poll.(*pollDesc).waitRead(...) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +internal/poll.(*FD).Read(0xc00010e180, 0xc000256000, 0x1000, 0x1000, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:159 +0x1a5 +net.(*netFD).Read(0xc00010e180, 0xc000256000, 0x1000, 0x1000, 0x103b1dc, 0xc000199b58, 0x10680e0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_posix.go:55 +0x4f +net.(*conn).Read(0xc000010008, 0xc000256000, 0x1000, 0x1000, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/net.go:182 +0x8e +net/http.(*persistConn).Read(0xc0000cea20, 0xc000256000, 0x1000, 0x1000, 0xc00009e300, 0xc000199c58, 0x10074b5) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:1887 +0x77 +bufio.(*Reader).fill(0xc0001801e0) + /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:101 +0x105 +bufio.(*Reader).Peek(0xc0001801e0, 0x1, 0x0, 0x0, 0x1, 0x0, 0xc00009e240) + /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:139 +0x4f +net/http.(*persistConn).readLoop(0xc0000cea20) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2040 +0x1a8 +created by net/http.(*Transport).dialConn + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:1708 +0xcb7 + +goroutine 54 [IO wait]: +internal/poll.runtime_pollWait(0x1e91cb8, 0x72, 0x14e6ca0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55 +internal/poll.(*pollDesc).wait(0xc00019e098, 0x72, 0x14e6c00, 0x16db878, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45 +internal/poll.(*pollDesc).waitRead(...) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +internal/poll.(*FD).Read(0xc00019e080, 0xc00007c311, 0x1, 0x1, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:159 +0x1a5 +net.(*netFD).Read(0xc00019e080, 0xc00007c311, 0x1, 0x1, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_posix.go:55 +0x4f +net.(*conn).Read(0xc000186028, 0xc00007c311, 0x1, 0x1, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/net.go:182 +0x8e +net/http.(*connReader).backgroundRead(0xc00007c300) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:690 +0x58 +created by net/http.(*connReader).startBackgroundRead + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:686 +0xd5 diff --git a/examples/goroutine/2.pprof.lookup.goroutine.debug0.pb.gz b/examples/goroutine/2.pprof.lookup.goroutine.debug0.pb.gz new file mode 100644 index 0000000..f0add3c Binary files /dev/null and b/examples/goroutine/2.pprof.lookup.goroutine.debug0.pb.gz differ diff --git a/examples/goroutine/2.pprof.lookup.goroutine.debug1.txt b/examples/goroutine/2.pprof.lookup.goroutine.debug1.txt new file mode 100644 index 0000000..2168c93 --- /dev/null +++ b/examples/goroutine/2.pprof.lookup.goroutine.debug1.txt @@ -0,0 +1,73 @@ +goroutine profile: total 9 +2 @ 0x103b125 0x106cd1f 0x13ac44a 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x106cd1e time.Sleep+0xbe /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +# 0x13ac449 main.shortSleepLoop+0x29 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 + +1 @ 0x103b125 0x10083ef 0x100802b 0x13ac4ed 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x13ac4ec main.chanReceiveForever+0x4c /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:177 + +1 @ 0x103b125 0x103425b 0x106a1d5 0x10d8185 0x10d91c5 0x10d91a3 0x11b8a8f 0x11cb72e 0x12df52d 0x11707c5 0x117151d 0x1171754 0x1263c2c 0x12d96ca 0x12d96f9 0x12e09ba 0x12e5085 0x106fd81 +# 0x106a1d4 internal/poll.runtime_pollWait+0x54 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +# 0x10d8184 internal/poll.(*pollDesc).wait+0x44 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +# 0x10d91c4 internal/poll.(*pollDesc).waitRead+0x1a4 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +# 0x10d91a2 internal/poll.(*FD).Read+0x182 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:159 +# 0x11b8a8e net.(*netFD).Read+0x4e /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_posix.go:55 +# 0x11cb72d net.(*conn).Read+0x8d /usr/local/Cellar/go/1.15.6/libexec/src/net/net.go:182 +# 0x12df52c net/http.(*connReader).Read+0x1ac /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:798 +# 0x11707c4 bufio.(*Reader).fill+0x104 /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:101 +# 0x117151c bufio.(*Reader).ReadSlice+0x3c /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:360 +# 0x1171753 bufio.(*Reader).ReadLine+0x33 /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:389 +# 0x1263c2b net/textproto.(*Reader).readLineSlice+0x6b /usr/local/Cellar/go/1.15.6/libexec/src/net/textproto/reader.go:58 +# 0x12d96c9 net/textproto.(*Reader).ReadLine+0xa9 /usr/local/Cellar/go/1.15.6/libexec/src/net/textproto/reader.go:39 +# 0x12d96f8 net/http.readRequest+0xd8 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/request.go:1012 +# 0x12e09b9 net/http.(*conn).readRequest+0x199 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:984 +# 0x12e5084 net/http.(*conn).serve+0x704 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:1851 + +1 @ 0x103b125 0x103425b 0x106a1d5 0x10d8185 0x10d91c5 0x10d91a3 0x11b8a8f 0x11cb72e 0x12ff937 0x11707c5 0x117092f 0x13005e8 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x106a1d4 internal/poll.runtime_pollWait+0x54 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +# 0x10d8184 internal/poll.(*pollDesc).wait+0x44 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +# 0x10d91c4 internal/poll.(*pollDesc).waitRead+0x1a4 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +# 0x10d91a2 internal/poll.(*FD).Read+0x182 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:159 +# 0x11b8a8e net.(*netFD).Read+0x4e /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_posix.go:55 +# 0x11cb72d net.(*conn).Read+0x8d /usr/local/Cellar/go/1.15.6/libexec/src/net/net.go:182 +# 0x12ff936 net/http.(*persistConn).Read+0x76 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:1887 +# 0x11707c4 bufio.(*Reader).fill+0x104 /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:101 +# 0x117092e bufio.(*Reader).Peek+0x4e /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:139 +# 0x13005e7 net/http.(*persistConn).readLoop+0x1a7 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2040 + +1 @ 0x103b125 0x103425b 0x106a1d5 0x10d8185 0x10dad7c 0x10dad5e 0x11ba005 0x11d4052 0x11d2ee5 0x12e9de6 0x12e9b17 0x13acce6 0x13acc90 0x106fd81 +# 0x106a1d4 internal/poll.runtime_pollWait+0x54 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +# 0x10d8184 internal/poll.(*pollDesc).wait+0x44 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +# 0x10dad7b internal/poll.(*pollDesc).waitRead+0x1fb /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +# 0x10dad5d internal/poll.(*FD).Accept+0x1dd /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:394 +# 0x11ba004 net.(*netFD).accept+0x44 /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_unix.go:172 +# 0x11d4051 net.(*TCPListener).accept+0x31 /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock_posix.go:139 +# 0x11d2ee4 net.(*TCPListener).Accept+0x64 /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock.go:261 +# 0x12e9de5 net/http.(*Server).Serve+0x265 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2937 +# 0x12e9b16 net/http.(*Server).ListenAndServe+0xb6 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2866 +# 0x13acce5 net/http.ListenAndServe+0x125 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:3120 +# 0x13acc8f main.main.func1+0xcf /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:123 + +1 @ 0x103b125 0x104afcf 0x130223c 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x130223b net/http.(*persistConn).writeLoop+0x11b /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2340 + +1 @ 0x103b125 0x106cd1f 0x13ac48b 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x106cd1e time.Sleep+0xbe /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +# 0x13ac48a main.sleepLoop+0x2a /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:171 + +1 @ 0x1069e1d 0x139efc2 0x139ed85 0x139b952 0x13ac965 0x13abe67 0x13ac352 0x103ad29 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x1069e1c runtime/pprof.runtime_goroutineProfileWithLabels+0x5c /usr/local/Cellar/go/1.15.6/libexec/src/runtime/mprof.go:716 +# 0x139efc1 runtime/pprof.writeRuntimeProfile+0xe1 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:724 +# 0x139ed84 runtime/pprof.writeGoroutine+0xa4 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:684 +# 0x139b951 runtime/pprof.(*Profile).WriteTo+0x3f1 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:331 +# 0x13ac964 main.glob..func4+0x64 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:60 +# 0x13abe66 main.writeProfiles+0x186 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:106 +# 0x13ac351 main.main+0x3d1 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:152 +# 0x103ad28 runtime.main+0x208 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:204 + diff --git a/examples/goroutine/2.pprof.lookup.goroutine.debug2.txt b/examples/goroutine/2.pprof.lookup.goroutine.debug2.txt new file mode 100644 index 0000000..bda4fee --- /dev/null +++ b/examples/goroutine/2.pprof.lookup.goroutine.debug2.txt @@ -0,0 +1,133 @@ +goroutine 1 [running]: +runtime/pprof.writeGoroutineStacks(0x14e5940, 0xc0000abc50, 0x101b8a5, 0xc000333d20) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:693 +0x9f +runtime/pprof.writeGoroutine(0x14e5940, 0xc0000abc50, 0x2, 0xc000333dc0, 0x10ee5c8) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:682 +0x45 +runtime/pprof.(*Profile).WriteTo(0x17179e0, 0x14e5940, 0xc0000abc50, 0x2, 0xc00002c210, 0xc0000ac4e0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/pprof/pprof.go:331 +0x3f2 +main.glob..func5(0x14e5940, 0xc0000abc50, 0xc000333eb0, 0x2) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:67 +0x65 +main.writeProfiles(0x2, 0xc0000c4008, 0x1466424) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:106 +0x187 +main.main() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:152 +0x3d2 + +goroutine 22 [sleep, 1 minutes]: +time.Sleep(0x3b9aca00) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.shortSleepLoop() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 +0x2a +created by main.indirectShortSleepLoop2 + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:185 +0x35 + +goroutine 3 [IO wait, 1 minutes]: +internal/poll.runtime_pollWait(0x1e91e88, 0x72, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55 +internal/poll.(*pollDesc).wait(0xc00019e018, 0x72, 0x0, 0x0, 0x1465786) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45 +internal/poll.(*pollDesc).waitRead(...) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +internal/poll.(*FD).Accept(0xc00019e000, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:394 +0x1fc +net.(*netFD).accept(0xc00019e000, 0x7d667d63cbbded3e, 0x1789ccbbded3e, 0x100000001) + /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_unix.go:172 +0x45 +net.(*TCPListener).accept(0xc000188060, 0x60006709, 0xc000196da8, 0x109abe6) + /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock_posix.go:139 +0x32 +net.(*TCPListener).Accept(0xc000188060, 0xc000196df8, 0x18, 0xc000001200, 0x12e9eec) + /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock.go:261 +0x65 +net/http.(*Server).Serve(0xc00019c000, 0x14ec6e0, 0xc000188060, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2937 +0x266 +net/http.(*Server).ListenAndServe(0xc00019c000, 0xc00019c000, 0x1475536) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2866 +0xb7 +net/http.ListenAndServe(...) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:3120 +main.main.func1(0xc000032120) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:123 +0x126 +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:121 +0xc5 + +goroutine 4 [sleep, 1 minutes]: +time.Sleep(0x3b9aca00) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.shortSleepLoop() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 +0x2a +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:130 +0x195 + +goroutine 5 [sleep, 1 minutes]: +time.Sleep(0x34630b8a000) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.sleepLoop(0x34630b8a000) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:171 +0x2b +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:131 +0x1bc + +goroutine 6 [chan receive, 1 minutes]: +main.chanReceiveForever() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:177 +0x4d +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:132 +0x1d4 + +goroutine 24 [select, 1 minutes]: +net/http.(*persistConn).writeLoop(0xc0000cea20) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2340 +0x11c +created by net/http.(*Transport).dialConn + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:1709 +0xcdc + +goroutine 23 [IO wait, 1 minutes]: +internal/poll.runtime_pollWait(0x1e91da0, 0x72, 0x14e6ca0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55 +internal/poll.(*pollDesc).wait(0xc00010e198, 0x72, 0x14e6c00, 0x16db878, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45 +internal/poll.(*pollDesc).waitRead(...) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +internal/poll.(*FD).Read(0xc00010e180, 0xc000256000, 0x1000, 0x1000, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:159 +0x1a5 +net.(*netFD).Read(0xc00010e180, 0xc000256000, 0x1000, 0x1000, 0x103b1dc, 0xc000199b58, 0x10680e0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_posix.go:55 +0x4f +net.(*conn).Read(0xc000010008, 0xc000256000, 0x1000, 0x1000, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/net.go:182 +0x8e +net/http.(*persistConn).Read(0xc0000cea20, 0xc000256000, 0x1000, 0x1000, 0xc00009e300, 0xc000199c58, 0x10074b5) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:1887 +0x77 +bufio.(*Reader).fill(0xc0001801e0) + /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:101 +0x105 +bufio.(*Reader).Peek(0xc0001801e0, 0x1, 0x0, 0x0, 0x1, 0x0, 0xc0001d0060) + /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:139 +0x4f +net/http.(*persistConn).readLoop(0xc0000cea20) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2040 +0x1a8 +created by net/http.(*Transport).dialConn + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:1708 +0xcb7 + +goroutine 41 [IO wait, 1 minutes]: +internal/poll.runtime_pollWait(0x1e91cb8, 0x72, 0x14e6ca0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55 +internal/poll.(*pollDesc).wait(0xc00019e098, 0x72, 0x14e6c00, 0x16db878, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45 +internal/poll.(*pollDesc).waitRead(...) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +internal/poll.(*FD).Read(0xc00019e080, 0xc000326000, 0x1000, 0x1000, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:159 +0x1a5 +net.(*netFD).Read(0xc00019e080, 0xc000326000, 0x1000, 0x1000, 0x203000, 0x203000, 0x203000) + /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_posix.go:55 +0x4f +net.(*conn).Read(0xc000186028, 0xc000326000, 0x1000, 0x1000, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/net.go:182 +0x8e +net/http.(*connReader).Read(0xc00007c300, 0xc000326000, 0x1000, 0x1000, 0x100000006, 0x10, 0x1819408) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:798 +0x1ad +bufio.(*Reader).fill(0xc000290060) + /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:101 +0x105 +bufio.(*Reader).ReadSlice(0xc000290060, 0xa, 0x1819408, 0xc000337988, 0x100f6d0, 0xc000110000, 0x100) + /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:360 +0x3d +bufio.(*Reader).ReadLine(0xc000290060, 0xc000110000, 0x1079694, 0xc0001a4000, 0x0, 0x1010038, 0x30) + /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:389 +0x34 +net/textproto.(*Reader).readLineSlice(0xc000182300, 0xc000110000, 0x10d7c4d, 0xc00019e080, 0x1068000, 0xc000282900) + /usr/local/Cellar/go/1.15.6/libexec/src/net/textproto/reader.go:58 +0x6c +net/textproto.(*Reader).ReadLine(...) + /usr/local/Cellar/go/1.15.6/libexec/src/net/textproto/reader.go:39 +net/http.readRequest(0xc000290060, 0x0, 0xc000110000, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/request.go:1012 +0xaa +net/http.(*conn).readRequest(0xc0000c6320, 0x14ed4a0, 0xc000322000, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:984 +0x19a +net/http.(*conn).serve(0xc0000c6320, 0x14ed4a0, 0xc000322000) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:1851 +0x705 +created by net/http.(*Server).Serve + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2969 +0x36c diff --git a/examples/goroutine/2.runtime.goroutineprofile.json b/examples/goroutine/2.runtime.goroutineprofile.json new file mode 100644 index 0000000..740b7a7 --- /dev/null +++ b/examples/goroutine/2.runtime.goroutineprofile.json @@ -0,0 +1,326 @@ +[ + { + "Stack0": [ + 20629256, + 20629212, + 20627047, + 20628306, + 17018153, + 17235329, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0 + ] + }, + { + "Stack0": [ + 17019173, + 17222943, + 20628554, + 17235329, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0 + ] + }, + { + "Stack0": [ + 17019173, + 16990811, + 17211861, + 17662341, + 17673596, + 17673566, + 18587653, + 18694226, + 18689765, + 19832294, + 19831575, + 20630758, + 20630672, + 17235329, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0 + ] + }, + { + "Stack0": [ + 17019173, + 17222943, + 20628554, + 17235329, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0 + ] + }, + { + "Stack0": [ + 17019173, + 17222943, + 20628619, + 17235329, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0 + ] + }, + { + "Stack0": [ + 17019173, + 16810991, + 16810027, + 20628717, + 17235329, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0 + ] + }, + { + "Stack0": [ + 17019173, + 17084367, + 19931708, + 17235329, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0 + ] + }, + { + "Stack0": [ + 17019173, + 16990811, + 17211861, + 17662341, + 17666501, + 17666467, + 18582159, + 18659118, + 19921207, + 18286533, + 18286895, + 19924456, + 17235329, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0 + ] + }, + { + "Stack0": [ + 17019173, + 16990811, + 17211861, + 17662341, + 17666501, + 17666467, + 18582159, + 18659118, + 19789101, + 18286533, + 18289949, + 18290516, + 19282988, + 19764938, + 19764985, + 19794362, + 19812485, + 17235329, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0, + 0 + ] + } +] diff --git a/examples/goroutine/2.runtime.stack.txt b/examples/goroutine/2.runtime.stack.txt new file mode 100644 index 0000000..6dfd93c --- /dev/null +++ b/examples/goroutine/2.runtime.stack.txt @@ -0,0 +1,127 @@ +goroutine 1 [running]: +main.glob..func1(0x14e5940, 0xc0000aa7b0, 0xc000064eb0, 0x2) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:29 +0x6f +main.writeProfiles(0x2, 0xc0000c4008, 0x1466424) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:106 +0x187 +main.main() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:152 +0x3d2 + +goroutine 22 [sleep, 1 minutes]: +time.Sleep(0x3b9aca00) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.shortSleepLoop() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 +0x2a +created by main.indirectShortSleepLoop2 + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:185 +0x35 + +goroutine 3 [IO wait, 1 minutes]: +internal/poll.runtime_pollWait(0x1e91e88, 0x72, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55 +internal/poll.(*pollDesc).wait(0xc00019e018, 0x72, 0x0, 0x0, 0x1465786) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45 +internal/poll.(*pollDesc).waitRead(...) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +internal/poll.(*FD).Accept(0xc00019e000, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:394 +0x1fc +net.(*netFD).accept(0xc00019e000, 0x7d667d63cbbded3e, 0x1789ccbbded3e, 0x100000001) + /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_unix.go:172 +0x45 +net.(*TCPListener).accept(0xc000188060, 0x60006709, 0xc000196da8, 0x109abe6) + /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock_posix.go:139 +0x32 +net.(*TCPListener).Accept(0xc000188060, 0xc000196df8, 0x18, 0xc000001200, 0x12e9eec) + /usr/local/Cellar/go/1.15.6/libexec/src/net/tcpsock.go:261 +0x65 +net/http.(*Server).Serve(0xc00019c000, 0x14ec6e0, 0xc000188060, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2937 +0x266 +net/http.(*Server).ListenAndServe(0xc00019c000, 0xc00019c000, 0x1475536) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2866 +0xb7 +net/http.ListenAndServe(...) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:3120 +main.main.func1(0xc000032120) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:123 +0x126 +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:121 +0xc5 + +goroutine 4 [sleep, 1 minutes]: +time.Sleep(0x3b9aca00) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.shortSleepLoop() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 +0x2a +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:130 +0x195 + +goroutine 5 [sleep, 1 minutes]: +time.Sleep(0x34630b8a000) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.sleepLoop(0x34630b8a000) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:171 +0x2b +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:131 +0x1bc + +goroutine 6 [chan receive, 1 minutes]: +main.chanReceiveForever() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:177 +0x4d +created by main.main + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:132 +0x1d4 + +goroutine 24 [select, 1 minutes]: +net/http.(*persistConn).writeLoop(0xc0000cea20) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2340 +0x11c +created by net/http.(*Transport).dialConn + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:1709 +0xcdc + +goroutine 23 [IO wait, 1 minutes]: +internal/poll.runtime_pollWait(0x1e91da0, 0x72, 0x14e6ca0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55 +internal/poll.(*pollDesc).wait(0xc00010e198, 0x72, 0x14e6c00, 0x16db878, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45 +internal/poll.(*pollDesc).waitRead(...) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +internal/poll.(*FD).Read(0xc00010e180, 0xc000256000, 0x1000, 0x1000, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:159 +0x1a5 +net.(*netFD).Read(0xc00010e180, 0xc000256000, 0x1000, 0x1000, 0x103b1dc, 0xc000199b58, 0x10680e0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_posix.go:55 +0x4f +net.(*conn).Read(0xc000010008, 0xc000256000, 0x1000, 0x1000, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/net.go:182 +0x8e +net/http.(*persistConn).Read(0xc0000cea20, 0xc000256000, 0x1000, 0x1000, 0xc00009e300, 0xc000199c58, 0x10074b5) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:1887 +0x77 +bufio.(*Reader).fill(0xc0001801e0) + /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:101 +0x105 +bufio.(*Reader).Peek(0xc0001801e0, 0x1, 0x0, 0x0, 0x1, 0x0, 0xc0001d0060) + /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:139 +0x4f +net/http.(*persistConn).readLoop(0xc0000cea20) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:2040 +0x1a8 +created by net/http.(*Transport).dialConn + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/transport.go:1708 +0xcb7 + +goroutine 41 [IO wait, 1 minutes]: +internal/poll.runtime_pollWait(0x1e91cb8, 0x72, 0x14e6ca0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55 +internal/poll.(*pollDesc).wait(0xc00019e098, 0x72, 0x14e6c00, 0x16db878, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45 +internal/poll.(*pollDesc).waitRead(...) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +internal/poll.(*FD).Read(0xc00019e080, 0xc000326000, 0x1000, 0x1000, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:159 +0x1a5 +net.(*netFD).Read(0xc00019e080, 0xc000326000, 0x1000, 0x1000, 0x203000, 0x203000, 0x203000) + /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_posix.go:55 +0x4f +net.(*conn).Read(0xc000186028, 0xc000326000, 0x1000, 0x1000, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/net.go:182 +0x8e +net/http.(*connReader).Read(0xc00007c300, 0xc000326000, 0x1000, 0x1000, 0x100000006, 0x10, 0x1819408) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:798 +0x1ad +bufio.(*Reader).fill(0xc000290060) + /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:101 +0x105 +bufio.(*Reader).ReadSlice(0xc000290060, 0xa, 0x1819408, 0xc000337988, 0x100f6d0, 0xc000110000, 0x100) + /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:360 +0x3d +bufio.(*Reader).ReadLine(0xc000290060, 0xc000110000, 0x1079694, 0xc0001a4000, 0x0, 0x1010038, 0x30) + /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:389 +0x34 +net/textproto.(*Reader).readLineSlice(0xc000182300, 0xc000110000, 0x10d7c4d, 0xc00019e080, 0x1068000, 0xc000282900) + /usr/local/Cellar/go/1.15.6/libexec/src/net/textproto/reader.go:58 +0x6c +net/textproto.(*Reader).ReadLine(...) + /usr/local/Cellar/go/1.15.6/libexec/src/net/textproto/reader.go:39 +net/http.readRequest(0xc000290060, 0x0, 0xc000110000, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/request.go:1012 +0xaa +net/http.(*conn).readRequest(0xc0000c6320, 0x14ed4a0, 0xc000322000, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:984 +0x19a +net/http.(*conn).serve(0xc0000c6320, 0x14ed4a0, 0xc000322000) + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:1851 +0x705 +created by net/http.(*Server).Serve + /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:2969 +0x36c diff --git a/examples/goroutine/main.go b/examples/goroutine/main.go new file mode 100644 index 0000000..1011db4 --- /dev/null +++ b/examples/goroutine/main.go @@ -0,0 +1,186 @@ +package main + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "flag" + "fmt" + "io" + "io/ioutil" + "net/http" + _ "net/http/pprof" + "runtime" + "runtime/pprof" + "time" +) + +type Profile struct { + Name string + WriteTo func(w io.Writer) error +} + +var profiles = []Profile{ + { + Name: "runtime.stack.txt", + WriteTo: func(w io.Writer) error { + buf := make([]byte, 1024*1024) + n := runtime.Stack(buf, true) + buf = buf[:n] + _, err := w.Write(buf) + return err + }, + }, + { + Name: "runtime.goroutineprofile.json", + WriteTo: func(w io.Writer) error { + p := make([]runtime.StackRecord, 1000) + n, ok := runtime.GoroutineProfile(p) + if !ok { + return errors.New("runtime.GoroutineProfile: not ok") + } + p = p[0:n] + e := json.NewEncoder(w) + e.SetIndent("", " ") + return e.Encode(p) + }, + }, + { + Name: "pprof.lookup.goroutine.debug0.pb.gz", + WriteTo: func(w io.Writer) error { + profile := pprof.Lookup("goroutine") + return profile.WriteTo(w, 0) + }, + }, + { + Name: "pprof.lookup.goroutine.debug1.txt", + WriteTo: func(w io.Writer) error { + profile := pprof.Lookup("goroutine") + return profile.WriteTo(w, 1) + }, + }, + { + Name: "pprof.lookup.goroutine.debug2.txt", + WriteTo: func(w io.Writer) error { + profile := pprof.Lookup("goroutine") + return profile.WriteTo(w, 2) + }, + }, + { + Name: "net.http.pprof.goroutine.debug0.pb.gz", + WriteTo: func(w io.Writer) error { + return writeHttpProfile(w, 0) + }, + }, + { + Name: "net.http.pprof.goroutine.debug1.txt", + WriteTo: func(w io.Writer) error { + return writeHttpProfile(w, 1) + }, + }, + { + Name: "net.http.pprof.goroutine.debug2.txt", + WriteTo: func(w io.Writer) error { + return writeHttpProfile(w, 2) + }, + }, +} + +func writeHttpProfile(w io.Writer, debug int) error { + url := fmt.Sprintf("http://%s/debug/pprof/goroutine?debug=%d", listenAddr, debug) + res, err := http.Get(url) + if err != nil { + return err + } + defer res.Body.Close() + + _, err = io.Copy(w, res.Body) + return err +} + +func writeProfiles(n int) error { + for _, profile := range profiles { + buf := &bytes.Buffer{} + filename := fmt.Sprintf("%d.%s", n, profile.Name) + if err := profile.WriteTo(buf); err != nil { + return err + } else if err := ioutil.WriteFile(filename, buf.Bytes(), 0666); err != nil { + return err + } + } + return nil +} + +var listenAddr = "127.0.0.1:8080" + +func main() { + flag.Parse() + + errCh := make(chan error, 1) + go func() { + fmt.Printf("Listening for pprof requests on %s\n", listenAddr) + errCh <- http.ListenAndServe(listenAddr, nil) + }() + + labels := pprof.Labels("test_label", "test_value") + ctx := pprof.WithLabels(context.Background(), labels) + pprof.SetGoroutineLabels(ctx) + + go shortSleepLoop() + go sleepLoop(time.Hour) + go chanReceiveForever() + go indirectShortSleepLoop() + + sleep := time.Second + fmt.Printf("Sleeping for %s followed by gc\n", sleep) + + time.Sleep(time.Second) + runtime.GC() + + fmt.Printf("Dump 1\n") + if err := writeProfiles(1); err != nil { + panic(err) + } + + sleep = 1*time.Minute + 10*time.Second + fmt.Printf("Sleeping for %s followed by gc\n", sleep) + time.Sleep(sleep) + runtime.GC() + + fmt.Printf("Dump 2\n") + if err := writeProfiles(2); err != nil { + panic(err) + } + + fmt.Printf("Waiting forever\n") + + //fmt.Printf("waiting indefinitely so you can press ctrl+\\ to compare the output\n") + //runtime.GC() + <-errCh +} + +func shortSleepLoop() { + for { + time.Sleep(time.Second) + } +} + +func sleepLoop(d time.Duration) { + for { + time.Sleep(d) + } +} + +func chanReceiveForever() { + forever := make(chan struct{}) + <-forever +} + +func indirectShortSleepLoop() { + indirectShortSleepLoop2() +} + +func indirectShortSleepLoop2() { + go shortSleepLoop() +} diff --git a/goroutine-matrix.png b/goroutine-matrix.png new file mode 100644 index 0000000..b86beb3 Binary files /dev/null and b/goroutine-matrix.png differ diff --git a/goroutine.md b/goroutine.md new file mode 100644 index 0000000..528951b --- /dev/null +++ b/goroutine.md @@ -0,0 +1,218 @@ +This document was last updated for `go1.15.6` but probably still applies to older/newer versions for the most parts. + +# Go's Goroutine Profiler + +Go has various APIs to provide users with a list of **active** goroutines, their current stack trace, as well as various other properties. Some APIs expose this information as statistical summaries, while other APIs provide information for each individual goroutine. + +Despite the differences between the APIs, the [common](https://github.com/golang/go/blob/9b955d2d3fcff6a5bc8bce7bafdc4c634a28e95b/src/runtime/mprof.go#L729) [definition](https://github.com/golang/go/blob/9b955d2d3fcff6a5bc8bce7bafdc4c634a28e95b/src/runtime/traceback.go#L931) of an **active** goroutine seems to be: + +- It's not [`dead`](https://github.com/golang/go/blob/go1.15.6/src/runtime/runtime2.go#L65-L71) (just exited or is being reinitialized). +- It's not a [system goroutine](https://github.com/golang/go/blob/9b955d2d3fcff6a5bc8bce7bafdc4c634a28e95b/src/runtime/traceback.go#L1013-L1021) nor finalizer goroutine. + +In other words, goroutines that are running, waiting on locks, i/o, scheduling, etc. are all considered to be active, even so one might naively not think of them as such. + +## Performance Impact + +All Goroutine profiling available in Go requires an `O(N)` **stop-the-world** phase where `N` is the number of allocated goroutines. A [naive benchmark](https://github.com/felixge/fgprof/blob/fe01e87ceec08ea5024e8168f88468af8f818b62/fgprof_test.go#L35-L78) [indicates](https://github.com/felixge/fgprof/blob/master/BenchmarkProfilerGoroutines.txt) that the world is stopped for ~1µs per goroutine when using the [runtime.GoroutineProfile()](https://golang.org/pkg/runtime/#GoroutineProfile) API. But this number is likely to fluctuate in response to other factors such as the average stack depth of the program. + +As a rule of thumb, applications that are extremely latency sensitive and make use of thousands of active goroutines might want to be a little careful with goroutine profiling in production. That being said, large number of goroutines, and perhaps even Go itself, might not be good idea for such applications to begin with. + +Most applications that can tolerate a few ms of ocassional extra latency should have no issues with continous goroutine profiling in production. + +## Goroutine Properties + +Goroutines have a lot of [properties](https://github.com/golang/go/blob/go1.15.6/src/runtime/runtime2.go#L406-L486) that can help to debug Go applications. The ones below are particulary interesting and exposed via the APIs described later on in this document to varying degrees. + +- [`goid`](https://github.com/golang/go/blob/go1.15.6/src/runtime/runtime2.go#L428): The unique id of the goroutine, the main goroutine has id `1`. +- [`atomicstatus`](https://github.com/golang/go/blob/go1.15.6/src/runtime/runtime2.go#L14-L105): The status of the goroutine, one of the following: + - `idle`: just got allocated + - `runnable`: on a run queue, waiting to be scheduled + - `running`: executing on an OS thread + - `syscall`: blocked on a syscall + - `waiting`: parked by the scheduler, see `g.waitreason` + - `dead`: just exited or being reinitialized + - `copystack`: stack is currently being moved + - `preempted`: just preempted itself +- [`waitreason`](https://github.com/golang/go/blob/go1.15.6/src/runtime/runtime2.go#L996-L1024): The reason a goroutine is in `waiting` status, e.g. sleep, channel operations, i/o, gc, etc. +- [`waitsince`](https://github.com/golang/go/blob/go1.15.6/src/runtime/runtime2.go#L430): The approximate timestamp a goroutine has entered `waiting` or `syscall` status as determined by the first gc after the wait started. +- [`labels`](https://github.com/golang/go/blob/go1.15.6/src/runtime/runtime2.go#L472): A set of key/value [profiler labels](https://rakyll.org/profiler-labels/) that can be attached to goroutines. +- `stack trace`: The function that is currently being executed as well as its callers. This is exposed as either a plain text output of filenames, function names and line numbers or a slice of program counter addresses (pcs). 🚧 *Research more details on this, e.g. can func/file/line text be converted to pcs?* +- [`gopc`](https://github.com/golang/go/blob/go1.15.6/src/runtime/runtime2.go#L466): The program counter address (pc) of the `go ...` call that caused this goroutine to be created. Can be converted to the file, function name and line number. +- [`lockedm`](https://github.com/golang/go/blob/go1.15.6/src/runtime/runtime2.go#L460): The thread this goroutine is locked to, if any. + +The feature matrix below give you a quick idea on the current availability of these properties through the various APIs. Also available as a [google sheet](https://docs.google.com/spreadsheets/d/1txMRjhDA0NC9eSNRRUMMFI5uWJ3FBnACGVjXYT1gKig/edit?usp=sharing). + +![goroutine feature matrix](./goroutine-matrix.png) + +## APIs + +### [`runtime.Stack()`](https://golang.org/pkg/runtime/#Stack) / [`pprof.Lookup(debug=2)`](https://golang.org/pkg/runtime/pprof/#Lookup) + +This returns unstructured text output showing the stack of all active goroutines as well as the properties listed in the feature matrix above. + +The `waitsince` property is included as `nanotime() - gp.waitsince()` in minutes, but only if the duration exceeds 1 minute. + +`pprof.Lookup(debug=2)` is a simplified alias for how this profile is used. The actual invocation looks like this: + +```go +profile := pprof.Lookup("goroutine") +profile.WriteTo(os.Stdout, 2) +``` + +The profile implementation itself simply invokes `runtime.Stack()`. + +Below is a truncated example of the returned output, see [2.runtime.stack.txt](./examples/goroutine/2.runtime.stack.txt) for a full example. + +``` +goroutine 1 [running]: +main.glob..func1(0x14e5940, 0xc0000aa7b0, 0xc000064eb0, 0x2) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:29 +0x6f +main.writeProfiles(0x2, 0xc0000c4008, 0x1466424) + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:106 +0x187 +main.main() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:152 +0x3d2 + +goroutine 22 [sleep, 1 minutes]: +time.Sleep(0x3b9aca00) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +0xbf +main.shortSleepLoop() + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 +0x2a +created by main.indirectShortSleepLoop2 + /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:185 +0x35 + +goroutine 3 [IO wait, 1 minutes]: +internal/poll.runtime_pollWait(0x1e91e88, 0x72, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +0x55 +internal/poll.(*pollDesc).wait(0xc00019e018, 0x72, 0x0, 0x0, 0x1465786) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45 +internal/poll.(*pollDesc).waitRead(...) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +internal/poll.(*FD).Accept(0xc00019e000, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0) + /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:394 +0x1fc + +... +``` + +### [`pprof.Lookup(debug=1)`](https://golang.org/pkg/runtime/pprof/#Lookup) + +This profiling method is invoked the same way as `pprof.Lookup(debug=2)`, but produces very different data: + +- Instead of listing individual goroutines, goroutines with the same stack/labels are listed once along with their count. +- pprof labels are included (`debug=2` does not include them). +- Most other goroutine properties from debug=2 are not included. +- The output format is also text based, but looks very different than `debug=2`. + +Below is a truncated example of the returned output, see [2.pprof.lookup.goroutine.debug1.txt](./examples/goroutine/2.pprof.lookup.goroutine.debug1.txt) for a full example. + +``` +goroutine profile: total 9 +2 @ 0x103b125 0x106cd1f 0x13ac44a 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x106cd1e time.Sleep+0xbe /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 +# 0x13ac449 main.shortSleepLoop+0x29 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 + +1 @ 0x103b125 0x10083ef 0x100802b 0x13ac4ed 0x106fd81 +# labels: {"test_label":"test_value"} +# 0x13ac4ec main.chanReceiveForever+0x4c /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:177 + +1 @ 0x103b125 0x103425b 0x106a1d5 0x10d8185 0x10d91c5 0x10d91a3 0x11b8a8f 0x11cb72e 0x12df52d 0x11707c5 0x117151d 0x1171754 0x1263c2c 0x12d96ca 0x12d96f9 0x12e09ba 0x12e5085 0x106fd81 +# 0x106a1d4 internal/poll.runtime_pollWait+0x54 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/netpoll.go:222 +# 0x10d8184 internal/poll.(*pollDesc).wait+0x44 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:87 +# 0x10d91c4 internal/poll.(*pollDesc).waitRead+0x1a4 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_poll_runtime.go:92 +# 0x10d91a2 internal/poll.(*FD).Read+0x182 /usr/local/Cellar/go/1.15.6/libexec/src/internal/poll/fd_unix.go:159 +# 0x11b8a8e net.(*netFD).Read+0x4e /usr/local/Cellar/go/1.15.6/libexec/src/net/fd_posix.go:55 +# 0x11cb72d net.(*conn).Read+0x8d /usr/local/Cellar/go/1.15.6/libexec/src/net/net.go:182 +# 0x12df52c net/http.(*connReader).Read+0x1ac /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:798 +# 0x11707c4 bufio.(*Reader).fill+0x104 /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:101 +# 0x117151c bufio.(*Reader).ReadSlice+0x3c /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:360 +# 0x1171753 bufio.(*Reader).ReadLine+0x33 /usr/local/Cellar/go/1.15.6/libexec/src/bufio/bufio.go:389 +# 0x1263c2b net/textproto.(*Reader).readLineSlice+0x6b /usr/local/Cellar/go/1.15.6/libexec/src/net/textproto/reader.go:58 +# 0x12d96c9 net/textproto.(*Reader).ReadLine+0xa9 /usr/local/Cellar/go/1.15.6/libexec/src/net/textproto/reader.go:39 +# 0x12d96f8 net/http.readRequest+0xd8 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/request.go:1012 +# 0x12e09b9 net/http.(*conn).readRequest+0x199 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:984 +# 0x12e5084 net/http.(*conn).serve+0x704 /usr/local/Cellar/go/1.15.6/libexec/src/net/http/server.go:1851 + +... +``` + +### [`pprof.Lookup(debug=0)`](https://golang.org/pkg/runtime/pprof/#Lookup) + +This profiling method is invoked the same way as `pprof.Lookup(debug=1)`, and produces the same data. The only difference is that the data format is the [pprof](./pprof.md) protocol buffer format. + +Below is a truncated example of the returned output as reported by `go tool pprof -raw`, see [2.pprof.lookup.goroutine.debug0.pb.gz](./examples/goroutine/2.pprof.lookup.goroutine.debug0.pb.gz) for a full example. + +``` +PeriodType: goroutine count +Period: 1 +Time: 2021-01-14 16:46:23.697667 +0100 CET +Samples: +goroutine/count + 2: 1 2 3 + test_label:[test_value] + 1: 1 4 5 6 + test_label:[test_value] + 1: 1 7 8 9 10 11 12 13 14 15 16 17 18 19 20 + 1: 1 7 8 9 10 11 12 21 14 22 23 + test_label:[test_value] + 1: 1 7 8 9 24 25 26 27 28 29 30 + 1: 1 31 32 + test_label:[test_value] + 1: 1 2 33 + test_label:[test_value] + 1: 34 35 36 37 38 39 40 41 + test_label:[test_value] +Locations + 1: 0x103b124 M=1 runtime.gopark /usr/local/Cellar/go/1.15.6/libexec/src/runtime/proc.go:306 s=0 + 2: 0x106cd1e M=1 time.Sleep /usr/local/Cellar/go/1.15.6/libexec/src/runtime/time.go:188 s=0 + 3: 0x13ac449 M=1 main.shortSleepLoop /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:165 s=0 + 4: 0x10083ee M=1 runtime.chanrecv /usr/local/Cellar/go/1.15.6/libexec/src/runtime/chan.go:577 s=0 + 5: 0x100802a M=1 runtime.chanrecv1 /usr/local/Cellar/go/1.15.6/libexec/src/runtime/chan.go:439 s=0 + 6: 0x13ac4ec M=1 main.chanReceiveForever /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/goroutine/main.go:177 s=0 +... +Mappings +1: 0x0/0x0/0x0 [FN] +``` + +### [`runtime.GoroutineProfile()`](https://golang.org/pkg/runtime/#GoroutineProfile) + +This function essentially returns a slice of all active goroutines and their current stack trace. The stack traces are given in the form of program addresses which can be resolved to function names using [`runtime.CallersFrames()`](https://golang.org/pkg/runtime/#CallersFrames). + +This method is used by [fgprof](https://github.com/felixge/fgprof) to implement wall clock profiling. + +The following features are not available, but might be interesting to propose to the Go project in the future: + +- Include goroutine properties outlined above that are not available yet, especially labels. +- Filter by pprof labels, this could reduce stop-the-world, but would require additional book keeping by the runtime. +- Limit the number of returned goroutines to a random subset, could also reduce stop-the-world and might be easier to implement than filtering by label. + +Below is a truncated example of the returned output, see [2.runtime.goroutineprofile.json](./examples/goroutine/2.runtime.goroutineprofile.json) for a full example. + +```json +[ + { + "Stack0": [ + 20629256, + 20629212, + 20627047, + 20628306, + 17018153, + 17235329, + // ... + ] + }, + { + "Stack0": [ + 17019173, + 17222943, + 20628554, + 17235329, + // ... + ] + }, + // ... +] +``` + +### [`net/http/pprof`](https://golang.org/pkg/net/http/pprof/) + +This package exposes the [`pprof.Lookup("goroutine")`](https://golang.org/pkg/runtime/pprof/#Lookup) profiles described above via HTTP endpoints. The output is identical. \ No newline at end of file