golang には pprof というプロファイラが付いて来るらしいので使ってみた。 直接使ってもいいけど、net/http/pprof を使うと結果をウェブで見れて便利らしいので入門には良さそうということで今回はこちらを触ってみたのでメモ。
準備
net/http/pprof のページに書いてあるように net/http/pprof をコードに仕込んで起動する.
import _ "net/http/pprof"
func main() {
runtime.SetBlockProfileRate(1)
go func() {
log.Println(http.ListenAndServe("0.0.0.0:6060", nil))
}()
}
これで 6060 ポートにブラウザからアクセスすることでプロファイリング結果を見れるようになる。
なお、blocking profiler を有効にするために runtime.SetBlockProfileRateを呼んでいる。net/http/pprof のページに書いてなくてハマってた。
以下、go-pastel に net/http/pprof を仕込んでみて、実際に表示された結果を貼り付けていく。
pprof サーバで見れるもの
トップページ
ここから block, goroutine, heap, threadcreate, full goroutine stack dump のリンクをたどって各ページを見れる。ブロッキングの数、goroutine の数、OSスレッドの数などが見れる。
/debug/pprof/
profiles:
2 block
9 goroutine
72 heap
26 threadcreate
full goroutine stack dump
注: 本当はリンク付きのHTMLページです
block ページ
トップページから block ページへのリンクを辿って見れる。このページで結果をみるためには、runtime.SetBlockProfileRate を呼んで blocking profiler を有効にしておかなければならない。
blocking profiler によってブロッキングしているイベントのスタックトレースを一望することができる。「non-blocking / event-driven な処理を書いているつもりなのにパフォーマンスが出ない！どこかでブロックしているんじゃないか？」と疑わしくなった時の調査に便利そう。
--- contention:
cycles/second=2666824728
72217 1 @ 0x81b1f21 0x81b26cd 0x81b266d 0x81b22ee 0x81427e0 0x814293a 0x8148108 0x814ac56 0x80d76e0
# 0x81b1f21 sync.(*Mutex).Lock+0xd1 /usr/local/go/src/pkg/sync/mutex.go:66
# 0x81b26cd sync.(*Pool).pinSlow+0x3d /usr/local/go/src/pkg/sync/pool.go:166
# 0x81b266d sync.(*Pool).pin+0x8d /usr/local/go/src/pkg/sync/pool.go:159
# 0x81b22ee sync.(*Pool).Get+0x3e /usr/local/go/src/pkg/sync/pool.go:100
# 0x81427e0 net/http.newTextprotoReader+0x30 /usr/local/go/src/pkg/net/http/request.go:535
# 0x814293a net/http.ReadRequest+0x7a /usr/local/go/src/pkg/net/http/request.go:551
# 0x8148108 net/http.(*conn).readRequest+0x218 /usr/local/go/src/pkg/net/http/server.go:577
# 0x814ac56 net/http.(*conn).serve+0x516 /usr/local/go/src/pkg/net/http/server.go:1132
37166 1 @ 0x81b1f21 0x81b20c1 0x82041b9 0x8204aec 0x821794a 0x8216fab 0x82123e2 0x8219fee 0x81fca06 0x814d055 0x814d5d3 0x80c3e5b 0x8116575 0x80c3b0d 0x80d4f6e 0x80d76e0
# 0x81b1f21 sync.(*Mutex).Lock+0xd1 /usr/local/go/src/pkg/sync/mutex.go:66
# 0x81b20c1 sync.(*Once).Do+0x61 /usr/local/go/src/pkg/sync/once.go:37
# 0x82041b9 net.(*pollDesc).Init+0x49 /usr/local/go/src/pkg/net/fd_poll_runtime.go:34
# 0x8204aec net.(*netFD).init+0x4c /usr/local/go/src/pkg/net/fd_unix.go:48
# 0x821794a net.(*netFD).listenStream+0x2ba /usr/local/go/src/pkg/net/sock_posix.go:153
# 0x8216fab net.socket+0x20b /usr/local/go/src/pkg/net/sock_posix.go:78
# 0x82123e2 net.internetSocket+0xf2 /usr/local/go/src/pkg/net/ipsock_posix.go:137
# 0x8219fee net.ListenTCP+0x14e /usr/local/go/src/pkg/net/tcpsock_posix.go:294
# 0x81fca06 net.Listen+0x356 /usr/local/go/src/pkg/net/dial.go:269
# 0x814d055 net/http.(*Server).ListenAndServe+0x75 /usr/local/go/src/pkg/net/http/server.go:1684
# 0x814d5d3 net/http.ListenAndServe+0x73 /usr/local/go/src/pkg/net/http/server.go:1778
# 0x80c3e5b main.start+0x31b /home/sonots/src/github.com/sonots/go-pastel/main.go:203
# 0x8116575 github.com/codegangsta/cli.(*App).Run+0x805 /home/sonots/src/github.com/codegangsta/cli/app.go:130
# 0x80c3b0d main.main+0x24d /home/sonots/src/github.com/sonots/go-pastel/main.go:184
# 0x80d4f6e runtime.main+0x11e /usr/local/go/src/pkg/runtime/proc.c:247
goroutine ページ
その瞬間の goroutine のスタックトレースを見れる。スレッドダンプならぬ goroutine ダンプと言えるか。 full goroutine stack dump のページのほうが役に立ちそうなので、そちらを見れば良いかと思うので飛ばす。
goroutine profile: total 12
1 @ 0x825aee3 0x825acc9 0x8257f08 0x8161f7f 0x81620b5 0x814b141 0x814c4dc 0x814ccc5 0x814ad36 0x80d76d0
# 0x825aee3 runtime/pprof.writeRuntimeProfile+0xb3 /usr/local/go/src/pkg/runtime/pprof/pprof.go:540
# 0x825acc9 runtime/pprof.writeGoroutine+0x89 /usr/local/go/src/pkg/runtime/pprof/pprof.go:502
# 0x8257f08 runtime/pprof.(*Profile).WriteTo+0xb8 /usr/local/go/src/pkg/runtime/pprof/pprof.go:229
# 0x8161f7f net/http/pprof.handler.ServeHTTP+0x1bf /usr/local/go/src/pkg/net/http/pprof/pprof.go:165
# 0x81620b5 net/http/pprof.Index+0x125 /usr/local/go/src/pkg/net/http/pprof/pprof.go:177
# 0x814b141 net/http.HandlerFunc.ServeHTTP+0x41 /usr/local/go/src/pkg/net/http/server.go:1235
# 0x814c4dc net/http.(*ServeMux).ServeHTTP+0x12c /usr/local/go/src/pkg/net/http/server.go:1511
# 0x814ccc5 net/http.serverHandler.ServeHTTP+0x155 /usr/local/go/src/pkg/net/http/server.go:1673
# 0x814ad36 net/http.(*conn).serve+0x8c6 /usr/local/go/src/pkg/net/http/server.go:1174
1 @ 0x80d7424 0x80e9ce6 0x80e9542 0x82041e8 0x8204256 0x8207443 0x8219837 0x814d76e 0x814ced4 0x814ce1b 0x814d303 0x80c3e4f 0x81162a5 0x80c3b0d 0x80d4f5e 0x80d76d0
# 0x80e9ce6 netpollblock+0x116 /usr/local/go/src/pkg/runtime/netpoll.goc:349
# 0x80e9542 net.runtime_pollWait+0x62 /usr/local/go/src/pkg/runtime/netpoll.goc:146
# 0x82041e8 net.(*pollDesc).Wait+0x48 /usr/local/go/src/pkg/net/fd_poll_runtime.go:84
# 0x8204256 net.(*pollDesc).WaitRead+0x46 /usr/local/go/src/pkg/net/fd_poll_runtime.go:89
# 0x8207443 net.(*netFD).accept+0x2f3 /usr/local/go/src/pkg/net/fd_unix.go:409
# 0x8219837 net.(*TCPListener).AcceptTCP+0x57 /usr/local/go/src/pkg/net/tcpsock_posix.go:234
# 0x814d76e net/http.tcpKeepAliveListener.Accept+0x4e /usr/local/go/src/pkg/net/http/server.go:1947
# 0x814ced4 net/http.(*Server).Serve+0x94 /usr/local/go/src/pkg/net/http/server.go:1698
# 0x814ce1b net/http.(*Server).ListenAndServe+0x10b /usr/local/go/src/pkg/net/http/server.go:1688
# 0x814d303 net/http.ListenAndServe+0x73 /usr/local/go/src/pkg/net/http/server.go:1778
# 0x80c3e4f main.start+0x30f /home/sonots/src/github.com/sonots/go-pastel/main.go:202
# 0x81162a5 github.com/codegangsta/cli.(*App).Run+0x805 /home/sonots/src/github.com/codegangsta/cli/app.go:130
# 0x80c3b0d main.main+0x24d /home/sonots/src/github.com/sonots/go-pastel/main.go:184
# 0x80d4f5e runtime.main+0x11e /usr/local/go/src/pkg/runtime/proc.c:247
1 @ 0x80c9474 0x80d0a7e 0x80d76d0
# 0x80c9474 runtime.notetsleepg+0x54 /usr/local/go/src/pkg/runtime/lock_futex.c:198
# 0x80d0a7e runtime.MHeap_Scavenger+0xce /usr/local/go/src/pkg/runtime/mheap.c:532
1 @ 0x80d7424 0x80d74af 0x80cd76a 0x80d76d0
# 0x80cd76a bgsweep+0x9a /usr/local/go/src/pkg/runtime/mgc0.c:1993
1 @ 0x80d7424 0x80d74af 0x80ced75 0x80d76d0
# 0x80ced75 runfinq+0xc5 /usr/local/go/src/pkg/runtime/mgc0.c:2644
1 @ 0x80d7424 0x80d74af 0x80e0c21 0x80e1055 0x80f9849 0x80d76d0
# 0x80e0c21 chanrecv+0x1d1 /usr/local/go/src/pkg/runtime/chan.goc:298
# 0x80e1055 runtime.chanrecv2+0x35 /usr/local/go/src/pkg/runtime/chan.goc:358
# 0x80f9849 database/sql.(*DB).connectionOpener+0x49 /usr/local/go/src/pkg/database/sql/sql.go:583
1 @ 0x80d7424 0x80e9ce6 0x80e9542 0x82041e8 0x8204256 0x8207443 0x8219837 0x814d76e 0x814ced4 0x814ce1b 0x814d303 0x80c4f48 0x80d76d0
# 0x80e9ce6 netpollblock+0x116 /usr/local/go/src/pkg/runtime/netpoll.goc:349
# 0x80e9542 net.runtime_pollWait+0x62 /usr/local/go/src/pkg/runtime/netpoll.goc:146
# 0x82041e8 net.(*pollDesc).Wait+0x48 /usr/local/go/src/pkg/net/fd_poll_runtime.go:84
# 0x8204256 net.(*pollDesc).WaitRead+0x46 /usr/local/go/src/pkg/net/fd_poll_runtime.go:89
# 0x8207443 net.(*netFD).accept+0x2f3 /usr/local/go/src/pkg/net/fd_unix.go:409
# 0x8219837 net.(*TCPListener).AcceptTCP+0x57 /usr/local/go/src/pkg/net/tcpsock_posix.go:234
# 0x814d76e net/http.tcpKeepAliveListener.Accept+0x4e /usr/local/go/src/pkg/net/http/server.go:1947
# 0x814ced4 net/http.(*Server).Serve+0x94 /usr/local/go/src/pkg/net/http/server.go:1698
# 0x814ce1b net/http.(*Server).ListenAndServe+0x10b /usr/local/go/src/pkg/net/http/server.go:1688
# 0x814d303 net/http.ListenAndServe+0x73 /usr/local/go/src/pkg/net/http/server.go:1778
# 0x80c4f48 main.func·001+0x38 /home/sonots/src/github.com/sonots/go-pastel/main.go:191
1 @ 0x80d7424 0x80d74af 0x80ed2be 0x80d76d0
# 0x80ed2be timerproc+0x9e /usr/local/go/src/pkg/runtime/time.goc:252
3 @ 0x80d7424 0x80e9ce6 0x80e9542 0x82041e8 0x8204256 0x820575d 0x82134d6 0x8146021 0x8183948 0x81f058c 0x81f1067 0x81f10e0 0x8231f9c 0x8231d8e 0x81426a5 0x8147e38 0x814a986 0x80d76d0
# 0x80e9ce6 netpollblock+0x116 /usr/local/go/src/pkg/runtime/netpoll.goc:349
# 0x80e9542 net.runtime_pollWait+0x62 /usr/local/go/src/pkg/runtime/netpoll.goc:146
# 0x82041e8 net.(*pollDesc).Wait+0x48 /usr/local/go/src/pkg/net/fd_poll_runtime.go:84
# 0x8204256 net.(*pollDesc).WaitRead+0x46 /usr/local/go/src/pkg/net/fd_poll_runtime.go:89
# 0x820575d net.(*netFD).Read+0x28d /usr/local/go/src/pkg/net/fd_unix.go:232
# 0x82134d6 net.(*conn).Read+0xc6 /usr/local/go/src/pkg/net/net.go:122
# 0x8146021 net/http.(*liveSwitchReader).Read+0x91 /usr/local/go/src/pkg/net/http/server.go:206
# 0x8183948 io.(*LimitedReader).Read+0xd8 /usr/local/go/src/pkg/io/io.go:399
# 0x81f058c bufio.(*Reader).fill+0x14c /usr/local/go/src/pkg/bufio/bufio.go:97
# 0x81f1067 bufio.(*Reader).ReadSlice+0x1b7 /usr/local/go/src/pkg/bufio/bufio.go:298
# 0x81f10e0 bufio.(*Reader).ReadLine+0x60 /usr/local/go/src/pkg/bufio/bufio.go:326
# 0x8231f9c net/textproto.(*Reader).readLineSlice+0x7c /usr/local/go/src/pkg/net/textproto/reader.go:55
# 0x8231d8e net/textproto.(*Reader).ReadLine+0x4e /usr/local/go/src/pkg/net/textproto/reader.go:36
# 0x81426a5 net/http.ReadRequest+0xb5 /usr/local/go/src/pkg/net/http/request.go:556
# 0x8147e38 net/http.(*conn).readRequest+0x218 /usr/local/go/src/pkg/net/http/server.go:577
# 0x814a986 net/http.(*conn).serve+0x516 /usr/local/go/src/pkg/net/http/server.go:1132
1 @ 0x80d76d0
heap ページ
メモリの使用状況を見れる。ヒープダンプ。
下のほうに runtime.MemStats の値が表示されて、現在 Allocation されている全体のオブジェクト数、GCの回数などをみることができる。
それぞれのエントリの先頭に表示されている 1: 57344 [1: 57344] がそれぞれ live objects、live objects によって使用されているメモリ量、allocations のトータル数、全ての allocations によって使用されているメモリ量を示しているようだ。
これを直接見ても自分にはよくわからないが、go tool pprof をかますと良い感じに集計してくれるのでそれを使ったほうが良さそうだ。結果を下のほうに貼っておく。
heap profile: 27: 151712 [460: 210288] @ heap/1048576
1: 57344 [1: 57344] @ 0x80e6d21 0x80e68a2 0x80e7cbd 0x80e7d5f 0x80e3537 0x80e4535 0x80e4fcb 0x81d605d 0x8132a55 0x8162285 0x80c5026 0x80d4f1d 0x80d76d0
# 0x80e6d21 profilealloc+0xa1 /usr/local/go/src/pkg/runtime/malloc.goc:258
# 0x80e68a2 runtime.mallocgc+0x212 /usr/local/go/src/pkg/runtime/malloc.goc:197
# 0x80e7cbd cnew+0xad /usr/local/go/src/pkg/runtime/malloc.goc:836
# 0x80e7d5f runtime.cnewarray+0x3f /usr/local/go/src/pkg/runtime/malloc.goc:849
# 0x80e3537 hash_grow+0x67 /usr/local/go/src/pkg/runtime/hashmap.goc:336
# 0x80e4535 hash_insert+0x2d5 /usr/local/go/src/pkg/runtime/hashmap.goc:534
# 0x80e4fcb runtime.mapassign1+0x3b /usr/local/go/src/pkg/runtime/hashmap.goc:933
# 0x81d605d html.init+0xbd /usr/local/go/src/pkg/html/entity.go:2155
# 0x8132a55 html/template.init+0x75 /usr/local/go/src/pkg/html/template/url.go:105
# 0x8162285 net/http/pprof.init+0x75 /usr/local/go/src/pkg/net/http/pprof/pprof.go:205
# 0x80c5026 main.init+0x66 /home/sonots/src/github.com/sonots/go-pastel/version.go:3
# 0x80d4f1d runtime.main+0xdd /usr/local/go/src/pkg/runtime/proc.c:240
11: 45056 [11: 45056] @ 0x80e6d21 0x80e68a2 0x80e7cbd 0x80e7d5f 0x80eb0ab 0x80eafb2 0x81f025a 0x81f030e 0x8147139 0x8146f25 0x814d0a9 0x814ce1b 0x814d303 0x80c3e4f 0x81162a5 0x80c3b0d 0x80d4f5e 0x80d76d0
# 0x80e6d21 profilealloc+0xa1 /usr/local/go/src/pkg/runtime/malloc.goc:258
# 0x80e68a2 runtime.mallocgc+0x212 /usr/local/go/src/pkg/runtime/malloc.goc:197
# 0x80e7cbd cnew+0xad /usr/local/go/src/pkg/runtime/malloc.goc:836
# 0x80e7d5f runtime.cnewarray+0x3f /usr/local/go/src/pkg/runtime/malloc.goc:849
# 0x80eb0ab makeslice1+0x4b /usr/local/go/src/pkg/runtime/slice.goc:55
# 0x80eafb2 runtime.makeslice+0xb2 /usr/local/go/src/pkg/runtime/slice.goc:36
# 0x81f025a bufio.NewReaderSize+0xaa /usr/local/go/src/pkg/bufio/bufio.go:56
# 0x81f030e bufio.NewReader+0x3e /usr/local/go/src/pkg/bufio/bufio.go:62
# 0x8147139 net/http.newBufioReader+0x99 /usr/local/go/src/pkg/net/http/server.go:462
# 0x8146f25 net/http.(*Server).newConn+0x1e5 /usr/local/go/src/pkg/net/http/server.go:434
# 0x814d0a9 net/http.(*Server).Serve+0x269 /usr/local/go/src/pkg/net/http/server.go:1716
# 0x814ce1b net/http.(*Server).ListenAndServe+0x10b /usr/local/go/src/pkg/net/http/server.go:1688
# 0x814d303 net/http.ListenAndServe+0x73 /usr/local/go/src/pkg/net/http/server.go:1778
# 0x80c3e4f main.start+0x30f /home/sonots/src/github.com/sonots/go-pastel/main.go:202
# 0x81162a5 github.com/codegangsta/cli.(*App).Run+0x805 /home/sonots/src/github.com/codegangsta/cli/app.go:130
# 0x80c3b0d main.main+0x24d /home/sonots/src/github.com/sonots/go-pastel/main.go:184
# 0x80d4f5e runtime.main+0x11e /usr/local/go/src/pkg/runtime/proc.c:247
10: 40960 [10: 40960] @ 0x80e6d21 0x80e68a2 0x80e7cbd 0x80e7d5f 0x80eb0ab 0x80eafb2 0x8147301 0x8146f68 0x814d0a9 0x814ce1b 0x814d303 0x80c3e4f 0x81162a5 0x80c3b0d 0x80d4f5e 0x80d76d0
# 0x80e6d21 profilealloc+0xa1 /usr/local/go/src/pkg/runtime/malloc.goc:258
# 0x80e68a2 runtime.mallocgc+0x212 /usr/local/go/src/pkg/runtime/malloc.goc:197
# 0x80e7cbd cnew+0xad /usr/local/go/src/pkg/runtime/malloc.goc:836
# 0x80e7d5f runtime.cnewarray+0x3f /usr/local/go/src/pkg/runtime/malloc.goc:849
# 0x80eb0ab makeslice1+0x4b /usr/local/go/src/pkg/runtime/slice.goc:55
# 0x80eafb2 runtime.makeslice+0xb2 /usr/local/go/src/pkg/runtime/slice.goc:36
# 0x8147301 net/http.newBufioWriterSize+0x141 /usr/local/go/src/pkg/net/http/server.go:479
# 0x8146f68 net/http.(*Server).newConn+0x228 /usr/local/go/src/pkg/net/http/server.go:435
# 0x814d0a9 net/http.(*Server).Serve+0x269 /usr/local/go/src/pkg/net/http/server.go:1716
# 0x814ce1b net/http.(*Server).ListenAndServe+0x10b /usr/local/go/src/pkg/net/http/server.go:1688
# 0x814d303 net/http.ListenAndServe+0x73 /usr/local/go/src/pkg/net/http/server.go:1778
# 0x80c3e4f main.start+0x30f /home/sonots/src/github.com/sonots/go-pastel/main.go:202
# 0x81162a5 github.com/codegangsta/cli.(*App).Run+0x805 /home/sonots/src/github.com/codegangsta/cli/app.go:130
# 0x80c3b0d main.main+0x24d /home/sonots/src/github.com/sonots/go-pastel/main.go:184
# 0x80d4f5e runtime.main+0x11e /usr/local/go/src/pkg/runtime/proc.c:247
4: 8192 [4: 8192] @ 0x80e6d21 0x80e68a2 0x80e7cbd 0x80e7d5f 0x80eb0ab 0x80eafb2 0x8147301 0x8147fd4 0x814a986 0x80d76d0
# 0x80e6d21 profilealloc+0xa1 /usr/local/go/src/pkg/runtime/malloc.goc:258
# 0x80e68a2 runtime.mallocgc+0x212 /usr/local/go/src/pkg/runtime/malloc.goc:197
# 0x80e7cbd cnew+0xad /usr/local/go/src/pkg/runtime/malloc.goc:836
# 0x80e7d5f runtime.cnewarray+0x3f /usr/local/go/src/pkg/runtime/malloc.goc:849
# 0x80eb0ab makeslice1+0x4b /usr/local/go/src/pkg/runtime/slice.goc:55
# 0x80eafb2 runtime.makeslice+0xb2 /usr/local/go/src/pkg/runtime/slice.goc:36
# 0x8147301 net/http.newBufioWriterSize+0x141 /usr/local/go/src/pkg/net/http/server.go:479
# 0x8147fd4 net/http.(*conn).readRequest+0x3b4 /usr/local/go/src/pkg/net/http/server.go:595
# 0x814a986 net/http.(*conn).serve+0x516 /usr/local/go/src/pkg/net/http/server.go:1132
1: 160 [1: 160] @ 0x80e6d21 0x80e68a2 0x80e7cbd 0x80e7d0f 0x80d5f1f 0x80d8247 0x80d229f 0x80d541c 0x80d4d4f 0x80ed7e6
# 0x80e6d21 profilealloc+0xa1 /usr/local/go/src/pkg/runtime/malloc.goc:258
# 0x80e68a2 runtime.mallocgc+0x212 /usr/local/go/src/pkg/runtime/malloc.goc:197
# 0x80e7cbd cnew+0xad /usr/local/go/src/pkg/runtime/malloc.goc:836
# 0x80e7d0f runtime.cnew+0x3f /usr/local/go/src/pkg/runtime/malloc.goc:843
# 0x80d5f1f allocg+0x4f /usr/local/go/src/pkg/runtime/proc.c:701
# 0x80d8247 runtime.malg+0x27 /usr/local/go/src/pkg/runtime/proc.c:1770
# 0x80d229f runtime.mpreinit+0x2f /usr/local/go/src/pkg/runtime/os_linux.c:198
# 0x80d541c mcommoninit+0xbc /usr/local/go/src/pkg/runtime/proc.c:361
# 0x80d4d4f runtime.schedinit+0x4f /usr/local/go/src/pkg/runtime/proc.c:151
# 0x80ed7e6 _rt0_go+0xf6 /usr/local/go/src/pkg/runtime/asm_386.s:95
略
# runtime.MemStats
# Alloc = 11753416
# TotalAlloc = 505591624
# Sys = 45792420
# Lookups = 414016
# Mallocs = 14374517
# Frees = 14358539
# HeapAlloc = 11753416
# HeapSys = 28311552
# HeapIdle = 13172736
# HeapInuse = 15138816
# HeapReleased = 1843200
# HeapObjects = 15978
# Stack = 9396224 / 9961472
# MSpan = 145152 / 229376
# MCache = 4400 / 16384
# BuckHashSys = 730832
# NextGC = 23173280
# PauseNs = [196677 196565 262750 2460703 2953429 422471 433137 1342365 2675978 4903768 18665055 4277777 2107035 7967989 6097760 18441070 2696225 2451654 2783834 3507595 2596726 2461949 1173170 4422036 2855353 3421875 2939505 3963706 2491906 5297891 2463593 2548093 2100155 2900081 3110169 1096189 1974464 10982394 4348263 5374790 3151288 4321942 2517161 2245442 7336788 2745282 3527066 3316255 4865322 3435391 1943332 2362656 4934347 4204028 3874429 3348335 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 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 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 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 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 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 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 0 0 0 0]
# NumGC = 56
# EnableGC = true
# DebugGC = false
go tool pprof をかました結果。どの関数呼び出しで何MB割り当てたのかがわかる。
$ go tool pprof --text http://localhost:6060/debug/pprof/heap
Read http://localhost:6060/debug/pprof/symbol
Fetching /pprof/heap profile from localhost:6060 to
/tmp/0LF7buTCGA
Wrote profile to /tmp/0LF7buTCGA
Adjusting heap profiles for 1-in-524288 sampling rate
Total: 14.5 MB
7.5 51.7% 51.7% 7.5 51.7% net/http.newBufioWriterSize
5.5 37.9% 89.7% 5.5 37.9% bufio.NewReaderSize
0.5 3.4% 93.1% 0.5 3.4% allocg
0.5 3.4% 96.6% 0.5 3.4% html.init
0.5 3.4% 100.0% 0.5 3.4% sync.(*Pool).Put
0.0 0.0% 100.0% 0.5 3.4% _rt0_go
0.0 0.0% 100.0% 5.5 37.9% bufio.NewReader
0.0 0.0% 100.0% 10.5 72.4% github.com/codegangsta/cli.(*App).Run
0.0 0.0% 100.0% 0.5 3.4% html/template.init
0.0 0.0% 100.0% 0.5 3.4% main.init
0.0 0.0% 100.0% 10.5 72.4% main.main
0.0 0.0% 100.0% 10.5 72.4% main.start
0.0 0.0% 100.0% 0.5 3.4% mcommoninit
0.0 0.0% 100.0% 10.5 72.4% net/http.(*Server).ListenAndServe
0.0 0.0% 100.0% 10.5 72.4% net/http.(*Server).Serve
0.0 0.0% 100.0% 10.5 72.4% net/http.(*Server).newConn
0.0 0.0% 100.0% 3.0 20.7% net/http.(*conn).readRequest
0.0 0.0% 100.0% 3.0 20.7% net/http.(*conn).serve
0.0 0.0% 100.0% 10.5 72.4% net/http.ListenAndServe
0.0 0.0% 100.0% 0.5 3.4% net/http.ReadRequest
threadcreate ページ
OSスレッドを生成している箇所のスタックトレースを見れるようだ。 プログラム内ではruntime.GOMAXPROCS でCPU数に固定しているので ab (apache bench) で負荷をかけるなどしてもスレッド数は一定数以上には増えなかった。
threadcreate profile: total 18
10 @ 0x80d5e31 0x80d626e 0x80d6583 0x80d6797 0x80d9d7e 0x80d9ab3 0x80d5d19
# 0x80d626e newm+0x2e /usr/local/go/src/pkg/runtime/proc.c:917
# 0x80d6583 startm+0xb3 /usr/local/go/src/pkg/runtime/proc.c:996
# 0x80d6797 handoffp+0x1a7 /usr/local/go/src/pkg/runtime/proc.c:1014
# 0x80d9d7e retake+0x11e /usr/local/go/src/pkg/runtime/proc.c:2646
# 0x80d9ab3 sysmon+0x123 /usr/local/go/src/pkg/runtime/proc.c:2586
# 0x80d5d19 runtime.mstart+0xe9 /usr/local/go/src/pkg/runtime/proc.c:624
1 @ 0x80d5e31 0x80d605b 0x80c8a87 0x8124147 0x81203fa 0x80fa1b2 0x80fb76e 0x80fb6a9 0x80fbe36 0x80c35e9 0x814b411 0x814c7ac 0x814cf95 0x814b006 0x80d76e0
# 0x8124147 github.com/mattn/go-sqlite3._Cfunc_sqlite3_threadsafe+0x37 github.com/mattn/go-sqlite3/_obj/_cgo_defun.c:395
# 0x81203fa github.com/mattn/go-sqlite3.(*SQLiteDriver).Open+0x5a /home/sonots/src/github.com/mattn/go-sqlite3/sqlite3.go:234
# 0x80fa1b2 database/sql.(*DB).conn+0x422 /usr/local/go/src/pkg/database/sql/sql.go:666
# 0x80fb76e database/sql.(*DB).query+0x3e /usr/local/go/src/pkg/database/sql/sql.go:924
# 0x80fb6a9 database/sql.(*DB).Query+0x89 /usr/local/go/src/pkg/database/sql/sql.go:915
# 0x80fbe36 database/sql.(*DB).QueryRow+0x56 /usr/local/go/src/pkg/database/sql/sql.go:993
# 0x80c35e9 main.memoHandler+0x5b9 /home/sonots/src/github.com/sonots/go-pastel/main.go:125
# 0x814b411 net/http.HandlerFunc.ServeHTTP+0x41 /usr/local/go/src/pkg/net/http/server.go:1235
# 0x814c7ac net/http.(*ServeMux).ServeHTTP+0x12c /usr/local/go/src/pkg/net/http/server.go:1511
# 0x814cf95 net/http.serverHandler.ServeHTTP+0x155 /usr/local/go/src/pkg/net/http/server.go:1673
# 0x814b006 net/http.(*conn).serve+0x8c6 /usr/local/go/src/pkg/net/http/server.go:1174
1 @ 0x80d5e31 0x80d626e 0x80d5b7f 0x80ce11a 0x80e6a67 0x80e7df5 0x814282f 0x814293a 0x8148108 0x814ac56 0x80d76e0
# 0x80d626e newm+0x2e /usr/local/go/src/pkg/runtime/proc.c:917
# 0x80d5b7f runtime.starttheworld+0x16f /usr/local/go/src/pkg/runtime/proc.c:595
# 0x80ce11a runtime.gc+0x22a /usr/local/go/src/pkg/runtime/mgc0.c:2336
# 0x80e6a67 runtime.mallocgc+0x1d7 /usr/local/go/src/pkg/runtime/malloc.goc:205
# 0x80e7df5 runtime.new+0x35 /usr/local/go/src/pkg/runtime/malloc.goc:826
# 0x814282f net/http.newTextprotoReader+0x7f /usr/local/go/src/pkg/net/http/request.go:540
# 0x814293a net/http.ReadRequest+0x7a /usr/local/go/src/pkg/net/http/request.go:551
# 0x8148108 net/http.(*conn).readRequest+0x218 /usr/local/go/src/pkg/net/http/server.go:577
# 0x814ac56 net/http.(*conn).serve+0x516 /usr/local/go/src/pkg/net/http/server.go:1132
2 @ 0x80d5e31 0x80d626e 0x80d6583 0x80d67fb 0x80d70ee 0x80d72cb 0x80d75d8 0x80edb90
# 0x80d626e newm+0x2e /usr/local/go/src/pkg/runtime/proc.c:917
# 0x80d6583 startm+0xb3 /usr/local/go/src/pkg/runtime/proc.c:996
# 0x80d67fb wakep+0x5b /usr/local/go/src/pkg/runtime/proc.c:1056
# 0x80d70ee resetspinning+0x9e /usr/local/go/src/pkg/runtime/proc.c:1282
# 0x80d72cb schedule+0x10b /usr/local/go/src/pkg/runtime/proc.c:1346
# 0x80d75d8 park0+0x108 /usr/local/go/src/pkg/runtime/proc.c:1410
# 0x80edb90 runtime.mcall+0x40 /usr/local/go/src/pkg/runtime/asm_386.s:190
1 @ 0x80d5e31 0x80d626e 0x80d6583 0x80d67fb 0x80d70ee 0x80d72cb 0x80d7854 0x80edb90
# 0x80d626e newm+0x2e /usr/local/go/src/pkg/runtime/proc.c:917
# 0x80d6583 startm+0xb3 /usr/local/go/src/pkg/runtime/proc.c:996
# 0x80d67fb wakep+0x5b /usr/local/go/src/pkg/runtime/proc.c:1056
# 0x80d70ee resetspinning+0x9e /usr/local/go/src/pkg/runtime/proc.c:1282
# 0x80d72cb schedule+0x10b /usr/local/go/src/pkg/runtime/proc.c:1346
# 0x80d7854 goexit0+0x134 /usr/local/go/src/pkg/runtime/proc.c:1477
# 0x80edb90 runtime.mcall+0x40 /usr/local/go/src/pkg/runtime/asm_386.s:190
1 @ 0x80d5e31 0x80d626e 0x80d6583 0x80d6797 0x80d7d3f 0x80c9484 0x80d0a8e 0x80d76e0
# 0x80d626e newm+0x2e /usr/local/go/src/pkg/runtime/proc.c:917
# 0x80d6583 startm+0xb3 /usr/local/go/src/pkg/runtime/proc.c:996
# 0x80d6797 handoffp+0x1a7 /usr/local/go/src/pkg/runtime/proc.c:1014
# 0x80d7d3f runtime.entersyscallblock+0x13f /usr/local/go/src/pkg/runtime/proc.c:1574
# 0x80c9484 runtime.notetsleepg+0x54 /usr/local/go/src/pkg/runtime/lock_futex.c:197
# 0x80d0a8e runtime.MHeap_Scavenger+0xce /usr/local/go/src/pkg/runtime/mheap.c:532
1 @ 0x80d5e31 0x80d626e 0x80d4e8e 0x80d76e0
# 0x80d626e newm+0x2e /usr/local/go/src/pkg/runtime/proc.c:917
# 0x80d4e8e runtime.main+0x3e /usr/local/go/src/pkg/runtime/proc.c:219
1 @ 0x80d4d5f 0x80edab6
# 0x80edab6 _rt0_go+0xf6 /usr/local/go/src/pkg/runtime/asm_386.s:95
full goroutine stack dump ページ
その瞬間の goroutine のスタックトレースをみれる。スレッドダンプならぬ goroutine ダンプと言えるか。 どの goroutine が running なのか、IO wait しているのかなどが見れる。
「なんか固まったんだけど！」みたいな時に追うのに役立ちそう。
goroutine 28 [running]:
runtime/pprof.writeGoroutineStacks(0xb7fa3a88, 0x19f0e150, 0x0, 0x0)
/usr/local/go/src/pkg/runtime/pprof/pprof.go:511 +0x93
runtime/pprof.writeGoroutine(0xb7fa3a88, 0x19f0e150, 0x2, 0x0, 0x0)
/usr/local/go/src/pkg/runtime/pprof/pprof.go:500 +0x4f
runtime/pprof.(*Profile).WriteTo(0x84f1070, 0xb7fa3a88, 0x19f0e150, 0x2, 0x0, 0x0)
/usr/local/go/src/pkg/runtime/pprof/pprof.go:229 +0xb8
net/http/pprof.handler.ServeHTTP(0x199ea701, 0x9, 0xb7fa39d0, 0x19f0e150, 0x19f08770)
/usr/local/go/src/pkg/net/http/pprof/pprof.go:165 +0x1bf
net/http/pprof.Index(0xb7fa39d0, 0x19f0e150, 0x19f08770)
/usr/local/go/src/pkg/net/http/pprof/pprof.go:177 +0x125
net/http.HandlerFunc.ServeHTTP(0x840333c, 0xb7fa39d0, 0x19f0e150, 0x19f08770)
/usr/local/go/src/pkg/net/http/server.go:1235 +0x41
net/http.(*ServeMux).ServeHTTP(0x187005a0, 0xb7fa39d0, 0x19f0e150, 0x19f08770)
/usr/local/go/src/pkg/net/http/server.go:1511 +0x12c
net/http.serverHandler.ServeHTTP(0x187c2000, 0xb7fa39d0, 0x19f0e150, 0x19f08770)
/usr/local/go/src/pkg/net/http/server.go:1673 +0x155
net/http.(*conn).serve(0x187e8050)
/usr/local/go/src/pkg/net/http/server.go:1174 +0x8c6
created by net/http.(*Server).Serve
/usr/local/go/src/pkg/net/http/server.go:1721 +0x2be
goroutine 16 [IO wait, 1 minutes]:
net.runtime_pollWait(0xb7fa3870, 0x72, 0x0)
/usr/local/go/src/pkg/runtime/netpoll.goc:146 +0x62
net.(*pollDesc).Wait(0x187303b8, 0x72, 0x0, 0x0)
/usr/local/go/src/pkg/net/fd_poll_runtime.go:84 +0x48
net.(*pollDesc).WaitRead(0x187303b8, 0x0, 0x0)
/usr/local/go/src/pkg/net/fd_poll_runtime.go:89 +0x46
net.(*netFD).accept(0x18730380, 0x84032f0, 0x0, 0xb7fa2248, 0xb)
/usr/local/go/src/pkg/net/fd_unix.go:409 +0x2f3
net.(*TCPListener).AcceptTCP(0x1870e620, 0x4, 0x0, 0x0)
/usr/local/go/src/pkg/net/tcpsock_posix.go:234 +0x57
net/http.tcpKeepAliveListener.Accept(0x1870e620, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/server.go:1947 +0x4e
net/http.(*Server).Serve(0x18730340, 0xb7fa38e0, 0x1870e620, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/server.go:1698 +0x94
net/http.(*Server).ListenAndServe(0x18730340, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/server.go:1688 +0x10b
net/http.ListenAndServe(0x187407a0, 0xc, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/server.go:1778 +0x73
main.start(0x187047e0)
/home/sonots/src/github.com/sonots/go-pastel/main.go:202 +0x30f
github.com/codegangsta/cli.(*App).Run(0x18729ea0, 0x1870e000, 0x1, 0x1, 0x0, 0x0)
/home/sonots/src/github.com/codegangsta/cli/app.go:130 +0x805
main.main()
/home/sonots/src/github.com/sonots/go-pastel/main.go:184 +0x24d
goroutine 19 [finalizer wait, 11 minutes]:
runtime.park(0x80d7430, 0x850abf0, 0x84f85c9)
/usr/local/go/src/pkg/runtime/proc.c:1369 +0x94
runtime.parkunlock(0x850abf0, 0x84f85c9)
/usr/local/go/src/pkg/runtime/proc.c:1385 +0x3f
runfinq()
/usr/local/go/src/pkg/runtime/mgc0.c:2644 +0xc5
runtime.goexit()
/usr/local/go/src/pkg/runtime/proc.c:1445
goroutine 24 [chan receive, 11 minutes]:
database/sql.(*DB).connectionOpener(0x18730300)
/usr/local/go/src/pkg/database/sql/sql.go:583 +0x49
created by database/sql.Open
/usr/local/go/src/pkg/database/sql/sql.go:442 +0x1e4
goroutine 23 [IO wait]:
net.runtime_pollWait(0xb7fa3800, 0x72, 0x0)
/usr/local/go/src/pkg/runtime/netpoll.goc:146 +0x62
net.(*pollDesc).Wait(0x187c2078, 0x72, 0x0, 0x0)
/usr/local/go/src/pkg/net/fd_poll_runtime.go:84 +0x48
net.(*pollDesc).WaitRead(0x187c2078, 0x0, 0x0)
/usr/local/go/src/pkg/net/fd_poll_runtime.go:89 +0x46
net.(*netFD).accept(0x187c2040, 0x84032f0, 0x0, 0xb7fa2248, 0xb)
/usr/local/go/src/pkg/net/fd_unix.go:409 +0x2f3
net.(*TCPListener).AcceptTCP(0x187ca000, 0x4, 0x0, 0x0)
/usr/local/go/src/pkg/net/tcpsock_posix.go:234 +0x57
net/http.tcpKeepAliveListener.Accept(0x187ca000, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/server.go:1947 +0x4e
net/http.(*Server).Serve(0x187c2000, 0xb7fa38e0, 0x187ca000, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/server.go:1698 +0x94
net/http.(*Server).ListenAndServe(0x187c2000, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/server.go:1688 +0x10b
net/http.ListenAndServe(0x8388d08, 0xc, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/server.go:1778 +0x73
main.func·001()
/home/sonots/src/github.com/sonots/go-pastel/main.go:191 +0x38
created by main.start
/home/sonots/src/github.com/sonots/go-pastel/main.go:192 +0x45
goroutine 10610 [IO wait, 4 minutes]:
net.runtime_pollWait(0xb7fcc890, 0x72, 0x0)
/usr/local/go/src/pkg/runtime/netpoll.goc:146 +0x62
net.(*pollDesc).Wait(0x196f8678, 0x72, 0x0, 0x0)
/usr/local/go/src/pkg/net/fd_poll_runtime.go:84 +0x48
net.(*pollDesc).WaitRead(0x196f8678, 0x0, 0x0)
/usr/local/go/src/pkg/net/fd_poll_runtime.go:89 +0x46
net.(*netFD).Read(0x196f8640, 0x18957000, 0x1000, 0x1000, 0x0, 0xb7fa2248, 0xb)
/usr/local/go/src/pkg/net/fd_unix.go:232 +0x28d
net.(*conn).Read(0x196af5b8, 0x18957000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/net.go:122 +0xc6
net/http.(*liveSwitchReader).Read(0x1988dd74, 0x18957000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/server.go:206 +0x91
io.(*LimitedReader).Read(0x197066a0, 0x18957000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/io/io.go:399 +0xd8
bufio.(*Reader).fill(0x187b5b90)
/usr/local/go/src/pkg/bufio/bufio.go:97 +0x14c
bufio.(*Reader).ReadSlice(0x187b5b90, 0x835ee0a, 0x0, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/bufio/bufio.go:298 +0x1b7
bufio.(*Reader).ReadLine(0x187b5b90, 0x0, 0x0, 0x0, 0x196f8600, 0x0, 0x0)
/usr/local/go/src/pkg/bufio/bufio.go:326 +0x60
net/textproto.(*Reader).readLineSlice(0x18aabe40, 0x0, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/textproto/reader.go:55 +0x7c
net/textproto.(*Reader).ReadLine(0x18aabe40, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/textproto/reader.go:36 +0x4e
net/http.ReadRequest(0x187b5b90, 0x18bc69a0, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/request.go:556 +0xb5
net/http.(*conn).readRequest(0x1988dd60, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/server.go:577 +0x218
net/http.(*conn).serve(0x1988dd60)
/usr/local/go/src/pkg/net/http/server.go:1132 +0x516
created by net/http.(*Server).Serve
/usr/local/go/src/pkg/net/http/server.go:1721 +0x2be
goroutine 801 [syscall, 4 minutes]:
runtime.goexit()
/usr/local/go/src/pkg/runtime/proc.c:1445
goroutine 10509 [IO wait, 4 minutes]:
net.runtime_pollWait(0xb7fb93c0, 0x72, 0x0)
/usr/local/go/src/pkg/runtime/netpoll.goc:146 +0x62
net.(*pollDesc).Wait(0x197bfcf8, 0x72, 0x0, 0x0)
/usr/local/go/src/pkg/net/fd_poll_runtime.go:84 +0x48
net.(*pollDesc).WaitRead(0x197bfcf8, 0x0, 0x0)
/usr/local/go/src/pkg/net/fd_poll_runtime.go:89 +0x46
net.(*netFD).Read(0x197bfcc0, 0x188eb000, 0x1000, 0x1000, 0x0, 0xb7fa2248, 0xb)
/usr/local/go/src/pkg/net/fd_unix.go:232 +0x28d
net.(*conn).Read(0x1970c000, 0x188eb000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/net.go:122 +0xc6
net/http.(*liveSwitchReader).Read(0x198eba04, 0x188eb000, 0x1000, 0x1000, 0xa, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/server.go:206 +0x91
io.(*LimitedReader).Read(0x197002d0, 0x188eb000, 0x1000, 0x1000, 0x834e200, 0x0, 0x0)
/usr/local/go/src/pkg/io/io.go:399 +0xd8
bufio.(*Reader).fill(0x187b5230)
/usr/local/go/src/pkg/bufio/bufio.go:97 +0x14c
bufio.(*Reader).ReadSlice(0x187b5230, 0x1874050a, 0x0, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/bufio/bufio.go:298 +0x1b7
bufio.(*Reader).ReadLine(0x187b5230, 0x0, 0x0, 0x0, 0x197bfc00, 0x0, 0x0)
/usr/local/go/src/pkg/bufio/bufio.go:326 +0x60
net/textproto.(*Reader).readLineSlice(0x18bc23a0, 0x0, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/textproto/reader.go:55 +0x7c
net/textproto.(*Reader).ReadLine(0x18bc23a0, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/textproto/reader.go:36 +0x4e
net/http.ReadRequest(0x187b5230, 0x18c4f420, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/request.go:556 +0xb5
net/http.(*conn).readRequest(0x198eb9f0, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/server.go:577 +0x218
net/http.(*conn).serve(0x198eb9f0)
/usr/local/go/src/pkg/net/http/server.go:1132 +0x516
created by net/http.(*Server).Serve
/usr/local/go/src/pkg/net/http/server.go:1721 +0x2be
goroutine 106242 [IO wait]:
net.runtime_pollWait(0xb7fba7e0, 0x72, 0x0)
/usr/local/go/src/pkg/runtime/netpoll.goc:146 +0x62
net.(*pollDesc).Wait(0x19390478, 0x72, 0x0, 0x0)
/usr/local/go/src/pkg/net/fd_poll_runtime.go:84 +0x48
net.(*pollDesc).WaitRead(0x19390478, 0x0, 0x0)
/usr/local/go/src/pkg/net/fd_poll_runtime.go:89 +0x46
net.(*netFD).Read(0x19390440, 0x18d51000, 0x1000, 0x1000, 0x0, 0xb7fa2248, 0xb)
/usr/local/go/src/pkg/net/fd_unix.go:232 +0x28d
net.(*conn).Read(0x198725f8, 0x18d51000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/net.go:122 +0xc6
net/http.(*liveSwitchReader).Read(0x19d74d34, 0x18d51000, 0x1000, 0x1000, 0xa, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/server.go:206 +0x91
io.(*LimitedReader).Read(0x19b20ac0, 0x18d51000, 0x1000, 0x1000, 0x834e200, 0x0, 0x0)
/usr/local/go/src/pkg/io/io.go:399 +0xd8
bufio.(*Reader).fill(0x18d34240)
/usr/local/go/src/pkg/bufio/bufio.go:97 +0x14c
bufio.(*Reader).ReadSlice(0x18d34240, 0x1874050a, 0x0, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/bufio/bufio.go:298 +0x1b7
bufio.(*Reader).ReadLine(0x18d34240, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/bufio/bufio.go:326 +0x60
net/textproto.(*Reader).readLineSlice(0x1898e2c0, 0x0, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/textproto/reader.go:55 +0x7c
net/textproto.(*Reader).ReadLine(0x1898e2c0, 0x0, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/textproto/reader.go:36 +0x4e
net/http.ReadRequest(0x18d34240, 0x19f087e0, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/request.go:556 +0xb5
net/http.(*conn).readRequest(0x19d74d20, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/server.go:577 +0x218
net/http.(*conn).serve(0x19d74d20)
/usr/local/go/src/pkg/net/http/server.go:1132 +0x516
created by net/http.(*Server).Serve
/usr/local/go/src/pkg/net/http/server.go:1721 +0x2be
CPU profile
あとは http://localhost:6060/debug/pprof/profile というページが実はあるのだが、バイナリファイルが落ちてくるので go tool pprof をかまして参照する。
30-second CPU profile:
アクセスした瞬間にプロファイルをスタートして、30秒たったら止め、結果を返してくれる。
go tool pprof http://localhost:6060/debug/pprof/profile
pprof のプロンプトが起動するので、top などのコマンドを打って結果を表示する。使えるコマンドは help コマンドでみれる。
(pprof) top20
Total: 2183 samples
754 34.5% 34.5% 775 35.5% runtime.cgocall
583 26.7% 61.2% 583 26.7% _fallback_vdso
51 2.3% 63.6% 107 4.9% runtime.mallocgc
29 1.3% 64.9% 29 1.3% runtime.memmove
23 1.1% 66.0% 23 1.1% runtime.duffcopy
19 0.9% 66.8% 19 0.9% runtime.memclr
18 0.8% 67.7% 20 0.9% settype
18 0.8% 68.5% 18 0.8% sync/atomic.LoadUint64
10 0.5% 68.9% 16 0.7% runtime.MSpan_Sweep
10 0.5% 69.4% 20 0.9% runtime.entersyscall
10 0.5% 69.9% 15 0.7% runtime.mapaccess1_faststr
10 0.5% 70.3% 10 0.5% runtime.markscan
9 0.4% 70.7% 11 0.5% removespecial
9 0.4% 71.1% 23 1.1% runtime.makeslice
9 0.4% 71.6% 74 3.4% runtime.new
8 0.4% 71.9% 13 0.6% runtime.deferreturn
7 0.3% 72.2% 248 11.4% github.com/mattn/go-sqlite3.(*SQLiteRows).Next
7 0.3% 72.6% 7 0.3% runtime.atomicstore64
6 0.3% 72.8% 72 3.3% database/sql.(*DB).conn
6 0.3% 73.1% 11 0.5% exitsyscallfast
なお、プロファイラが起動すると、1秒に100回プログラムを停止して、その時点でスタックトレースを元にカウントするらしい。2183 samples なので 21.83 秒ほどプロファイラが起動していたことになる(あれ、30秒じゃなかったのか？)
１列目はカウントされたサンプルの数、２列目は全体サンプル数に対するその割合を表示している。 ３列目はサンプル数の累積割合を表示していて、２行目を見ると 61.2% となっているので上位２つで 61% をしめていることがわかる。 top コマンドはこのサンプル数をもとに上から順に表示している。
４列目、５列目はその関数がコールスタック上にあらわれた数とその割合を表示している。 たとえばruntime.mallocgc 関数は全サンプル数のうち 2.3% において running 状態であったが、 4.9% の割合でコールスタックにいた(自身のコールスタックと runtime.mallocgc を呼び出していた別の関数のコールスタック)ことがわかる。
４列目、５列目で sort するには -cum (cumulative) オプションを付ける
(pprof) top5 -cum
Total: 2218 samples
0 0.0% 0.0% 1904 85.8% runtime.gosched0
5 0.2% 0.2% 1609 72.5% net/http.(*conn).serve
1 0.0% 0.3% 1147 51.7% net/http.(*ServeMux).ServeHTTP
0 0.0% 0.3% 1147 51.7% net/http.serverHandler.ServeHTTP
4 0.2% 0.5% 1126 50.8% main.memoHandler
さらには、コールグラフを可視化することができて、web と打つと結果を svg にしてブラウザを起動し、こちら のようなグラフ画像を作ってくれる。
所感：しかしこれは、サンプル数なので、処理に時間がかかっていたのか呼び出し回数が多かったのか区別がつかないのではないか？
Further Reading
本記事は簡単なメモにすぎないがもっと詳しく知りたい場合は以下の記事を読むとよい。- http://blog.golang.org/profiling-go-programs
- (pprof) プロンプトで使えるコマンドなどをもっと詳しく解説している本家文書
- list コマンドなどは特に便利そう
- Debugging performance issues in Go programs
- net/http/pprof だけではなく pprof の使い方についてもよくまとまっている
