如何分析 Golang Web App Server
How to profile Golang Web App Server
我有一个使用 Go (httprouter/gokil) 编写的 Web 应用程序服务器，当我使用 siege -b -t10s -c255 对其进行测试时，它显示如下（最佳分数）：
POST API (read only query to database, cache query result to RAM)
Transaction rate: 4251.38 trans/sec (local without proxy)
Transaction rate: 2082.11 trans/sec (local with proxy)
Transaction rate: 1806.63 trans/sec (test server)
GET Realistic (static file request, multiple URL)
Transaction rate: 4417.75 trans/sec (local without proxy)
Transaction rate: 1419.58 trans/sec (local with proxy)
Transaction rate: 234.73 trans/sec (test server)
Transaction Rate: 40.50 trans/sec (other external site that use gokil)
GET One static file (getting /js/jquery.js)
Transaction rate: 4166.83 trans/sec (local without proxy)
Transaction rate: 2531.79 trans/sec (local with proxy)
Transaction rate: 31.39 trans/sec (test server)
Transaction rate: 20.95 trans/sec (other external site that use gokil)
For comparison, hello world
Transaction rate: 13838.83 trans/sec (plain Go https://play.golang.org/p/y8rJ4ZkclD )
Transaction rate: 5420.79 trans/sec (local without proxy https://gitlab.com/kokizzu/gokil/tree/master/_example )
Transaction rate: 2701.12 trans/sec (local with proxy)
local 的规格是 i7-4772HQ，三星 850 SSD。
我使用的代理是caddy。我使用的数据库是用于存储会话的 PostgreSQL 和 Redis。 test server 与千兆连接在同一个网络上。
问题是，如何衡量每个请求的时间：哪个 function/line 代码导致了瓶颈？因为我看其他benchmark Go 可以实现70k到171k rps.
我试过这个 blog，但它显示：
$ cd $GOPATH/src/gitlab.com/kokizzu/gokil/_example
$ go build
$ go tool pprof —text ./test
parsing profile: unrecognized profile format
没关系，从 this blog post 找到了方法，我看错了例子。
只需在 main 函数开始时添加 defer profile.Start(profile.CPUProfile).Stop()。
Import/Go得到github.com/pkg/profile
构建并 运行 程序，对其进行基准测试，退出程序，在行尾它会显示如下内容：
2016/11/24 18:41:24 profile: caught interrupt, stopping profiles
2016/11/24 18:41:24 profile: cpu profiling disabled, /tmp/profile627033993/cpu.pprof
- 运行 命令 pprof 命令
go tool pprof -text /tmp/profile627033993/cpu.pprof
它会显示这样的东西：
$ go tool pprof -text /tmp/profile627033993/cpu.pprof
12.89s of 16.31s total (79.03%)
Dropped 386 nodes (cum <= 0.08s)
flat flat% sum% cum cum%
7.26s 44.51% 44.51% 7.40s 45.37% syscall.Syscall
0.42s 2.58% 47.09% 0.62s 3.80% runtime.scanobject
0.38s 2.33% 49.42% 1.09s 6.68% runtime.mallocgc
0.32s 1.96% 51.38% 0.32s 1.96% runtime.memmove
0.27s 1.66% 53.03% 0.27s 1.66% runtime.futex
0.25s 1.53% 54.57% 1.21s 7.42% runtime.gentraceback
0.21s 1.29% 55.86% 0.59s 3.62% runtime.pcvalue
0.19s 1.16% 57.02% 0.19s 1.16% runtime.usleep
0.18s 1.10% 58.12% 0.18s 1.10% runtime.readvarint
0.15s 0.92% 59.04% 0.15s 0.92% runtime.heapBitsForObject
0.15s 0.92% 59.96% 0.15s 0.92% runtime.heapBitsSetType
0.14s 0.86% 60.82% 0.14s 0.86% runtime._ExternalCode
0.14s 0.86% 61.68% 0.14s 0.86% runtime.epollctl
0.13s 0.8% 62.48% 0.13s 0.8% runtime.rtsigprocmask
0.12s 0.74% 63.21% 0.16s 0.98% runtime.deferreturn
0.12s 0.74% 63.95% 0.17s 1.04% runtime.greyobject
0.12s 0.74% 64.68% 0.16s 0.98% syscall.Syscall6
0.11s 0.67% 65.36% 0.40s 2.45% runtime.adjustframe
0.11s 0.67% 66.03% 0.11s 0.67% runtime.adjustpointers
0.11s 0.67% 66.71% 0.11s 0.67% runtime.memclr
0.11s 0.67% 67.38% 0.29s 1.78% runtime.step
0.10s 0.61% 68.00% 1.53s 9.38% runtime.systemstack
0.07s 0.43% 68.42% 0.21s 1.29% runtime.mapassign1
0.07s 0.43% 68.85% 0.25s 1.53% runtime.rawstring
0.06s 0.37% 69.22% 0.17s 1.04% runtime.scanblock
0.06s 0.37% 69.59% 0.17s 1.04% time.Time.AppendFormat
0.05s 0.31% 69.90% 0.12s 0.74% runtime.casgstatus
0.05s 0.31% 70.20% 0.10s 0.61% runtime.lock
0.05s 0.31% 70.51% 0.56s 3.43% runtime.newobject
0.05s 0.31% 70.82% 0.18s 1.10% runtime.tracebackdefers
0.04s 0.25% 71.06% 0.75s 4.60% bufio.(*Reader).ReadSlice
0.04s 0.25% 71.31% 0.32s 1.96% fmt.(*pp).doPrintf
0.04s 0.25% 71.55% 7.22s 44.27% gitlab.com/kokizzu/gokil/W.LoadSession
0.04s 0.25% 71.80% 0.32s 1.96% runtime.scanframeworker
0.04s 0.25% 72.04% 0.12s 0.74% runtime.typedmemmove
0.03s 0.18% 72.23% 0.25s 1.53% fmt.(*pp).printArg
0.03s 0.18% 72.41% 0.47s 2.88% github.com/op/go-logging.(*stringFormatter).Format
0.03s 0.18% 72.59% 0.67s 4.11% net.(*netFD).Read
0.03s 0.18% 72.78% 12.43s 76.21% net/http.(*conn).serve
0.03s 0.18% 72.96% 0.11s 0.67% runtime.(*mcentral).cacheSpan
0.03s 0.18% 73.15% 0.10s 0.61% runtime.deferproc.func1
0.03s 0.18% 73.33% 0.10s 0.61% runtime.exitsyscall
0.03s 0.18% 73.51% 0.09s 0.55% runtime.makemap
0.03s 0.18% 73.70% 0.72s 4.41% runtime.markroot
0.03s 0.18% 73.88% 0.09s 0.55% runtime.runqgrab
0.02s 0.12% 74.00% 0.65s 3.99% github.com/garyburd/redigo/redis.(*conn).readLine
0.02s 0.12% 74.13% 0.78s 4.78% github.com/garyburd/redigo/redis.(*conn).readReply
0.02s 0.12% 74.25% 0.09s 0.55% github.com/garyburd/redigo/redis.(*conn).writeCommand
0.02s 0.12% 74.37% 0.39s 2.39% gitlab.com/kokizzu/gokil/Z.(*TemplateChain).Render
0.02s 0.12% 74.49% 1.28s 7.85% main.AuthFilter
0.02s 0.12% 74.62% 0.32s 1.96% net.(*netFD).accept
0.02s 0.12% 74.74% 4.74s 29.06% net.dialSingle
0.02s 0.12% 74.86% 0.11s 0.67% net/http.(*connReader).Read
0.02s 0.12% 74.98% 0.66s 4.05% net/http.(*response).finishRequest
0.02s 0.12% 75.11% 0.49s 3.00% net/http.readRequest
0.02s 0.12% 75.23% 0.10s 0.61% runtime.SetFinalizer
0.02s 0.12% 75.35% 0.10s 0.61% runtime.concatstrings
0.02s 0.12% 75.48% 0.68s 4.17% runtime.findrunnable
0.02s 0.12% 75.60% 0.27s 1.66% runtime.makeslice
0.02s 0.12% 75.72% 0.90s 5.52% runtime.morestack
0.02s 0.12% 75.84% 0.12s 0.74% runtime.newarray
0.02s 0.12% 75.97% 0.32s 1.96% runtime.pcdatavalue
0.02s 0.12% 76.09% 0.27s 1.66% runtime.rawstringtmp
0.02s 0.12% 76.21% 0.78s 4.78% runtime.schedule
0.02s 0.12% 76.33% 0.57s 3.49% syscall.read
0.01s 0.061% 76.39% 0.71s 4.35% bufio.(*Reader).fill
0.01s 0.061% 76.46% 1.82s 11.16% bufio.(*Writer).flush
0.01s 0.061% 76.52% 0.34s 2.08% fmt.Sprintf
0.01s 0.061% 76.58% 5.19s 31.82% github.com/garyburd/redigo/redis.(*Pool).get
0.01s 0.061% 76.64% 0.25s 1.53% github.com/garyburd/redigo/redis.(*Pool).put
0.01s 0.061% 76.70% 2.14s 13.12% github.com/garyburd/redigo/redis.(*conn).Do
0.01s 0.061% 76.76% 0.31s 1.90% github.com/garyburd/redigo/redis.(*pooledConnection).Close
0.01s 0.061% 76.82% 1.96s 12.02% github.com/garyburd/redigo/redis.(*pooledConnection).Do
0.01s 0.061% 76.89% 0.75s 4.60% github.com/op/go-logging.(*Logger).Notice
0.01s 0.061% 76.95% 0.74s 4.54% github.com/op/go-logging.(*backendFormatter).Log
0.01s 0.061% 77.01% 0.42s 2.58% gitlab.com/kokizzu/gokil/W.(*Context).Finish
0.01s 0.061% 77.07% 0.42s 2.58% gitlab.com/kokizzu/gokil/W.(*Context).Render
0.01s 0.061% 77.13% 10.37s 63.58% gitlab.com/kokizzu/gokil/W.(*Engine).ServeHTTP
0.01s 0.061% 77.19% 0.10s 0.61% gitlab.com/kokizzu/gokil/W.(*Session).parseIpAddr
0.01s 0.061% 77.25% 2.57s 15.76% gitlab.com/kokizzu/gokil/W.Logger
0.01s 0.061% 77.31% 0.37s 2.27% net.(*TCPListener).AcceptTCP
0.01s 0.061% 77.38% 0.68s 4.17% net.(*conn).Read
0.01s 0.061% 77.44% 1.62s 9.93% net.(*conn).Write
0.01s 0.061% 77.50% 4.62s 28.33% net.(*netFD).connect
0.01s 0.061% 77.56% 0.10s 0.61% net.(*pollDesc).init
0.01s 0.061% 77.62% 4.71s 28.88% net.doDialTCP
0.01s 0.061% 77.68% 0.09s 0.55% net.runtime_pollClose
0.01s 0.061% 77.74% 0.18s 1.10% net/http.(*chunkWriter).writeHeader
0.01s 0.061% 77.81% 10.38s 63.64% net/http.serverHandler.ServeHTTP
0.01s 0.061% 77.87% 0.43s 2.64% net/http.tcpKeepAliveListener.Accept
0.01s 0.061% 77.93% 0.14s 0.86% runtime.adjustdefers
0.01s 0.061% 77.99% 0.11s 0.67% runtime.callers.func1
0.01s 0.061% 78.05% 0.23s 1.41% runtime.convT2E
0.01s 0.061% 78.11% 0.12s 0.74% runtime.deferproc
0.01s 0.061% 78.17% 0.29s 1.78% runtime.funcspdelta
0.01s 0.061% 78.23% 0.14s 0.86% runtime.futexsleep
0.01s 0.061% 78.30% 0.24s 1.47% runtime.gcAssistAlloc
0.01s 0.061% 78.36% 1.18s 7.23% runtime.gcDrain
0.01s 0.061% 78.42% 0.20s 1.23% runtime.gcDrainN
0.01s 0.061% 78.48% 0.09s 0.55% runtime.gcMarkTermination
0.01s 0.061% 78.54% 0.10s 0.61% runtime.netpoll
0.01s 0.061% 78.60% 0.88s 5.40% runtime.newstack
0.01s 0.061% 78.66% 0.14s 0.86% runtime.notesleep
0.01s 0.061% 78.72% 0.64s 3.92% runtime.park_m
0.01s 0.061% 78.79% 0.10s 0.61% runtime.runqsteal
0.01s 0.061% 78.85% 0.59s 3.62% runtime.scang
0.01s 0.061% 78.91% 0.53s 3.25% runtime.scanstack
0.01s 0.061% 78.97% 0.14s 0.86% runtime.startm
0.01s 0.061% 79.03% 1.67s 10.24% syscall.Write
0 0% 79.03% 0.12s 0.74% bufio.(*Reader).ReadLine
0 0% 79.03% 1.82s 11.16% bufio.(*Writer).Flush
0 0% 79.03% 0.09s 0.55% bytes.(*Buffer).Write
0 0% 79.03% 0.14s 0.86% fmt.Fprintf
0 0% 79.03% 0.17s 1.04% github.com/fatih/color.(*Color).SprintfFunc.func1
0 0% 79.03% 0.17s 1.04% github.com/fatih/color.BlueString
0 0% 79.03% 0.17s 1.04% github.com/fatih/color.printString
0 0% 79.03% 5.21s 31.94% github.com/garyburd/redigo/redis.(*Pool).Get
0 0% 79.03% 0.17s 1.04% github.com/garyburd/redigo/redis.(*conn).Close
0 0% 79.03% 4.91s 30.10% github.com/garyburd/redigo/redis.(*xDialer).Dial
0 0% 79.03% 4.93s 30.23% github.com/garyburd/redigo/redis.Dial
0 0% 79.03% 0.73s 4.48% github.com/op/go-logging.(*LogBackend).Log
0 0% 79.03% 0.74s 4.54% github.com/op/go-logging.(*Logger).log
0 0% 79.03% 0.49s 3.00% github.com/op/go-logging.(*Record).Formatted
0 0% 79.03% 0.74s 4.54% github.com/op/go-logging.(*moduleLeveled).Log
0 0% 79.03% 0.46s 2.82% gitlab.com/kokizzu/gokil/W.(*Engine).StartServer
0 0% 79.03% 0.30s 1.84% gitlab.com/kokizzu/gokil/W.(*Session).Save
0 0% 79.03% 0.73s 4.48% gitlab.com/kokizzu/gokil/W.(*Session).Touch
0 0% 79.03% 5.16s 31.64% gitlab.com/kokizzu/gokil/W.InitSession.func1
0 0% 79.03% 1.32s 8.09% gitlab.com/kokizzu/gokil/W.Recover
0 0% 79.03% 0.73s 4.48% gitlab.com/kokizzu/gokil/W.Session.ShouldRenew
0 0% 79.03% 0.09s 0.55% gitlab.com/kokizzu/gokil/W.hashCookie
0 0% 79.03% 0.24s 1.47% gitlab.com/kokizzu/gokil/W.newSession
0 0% 79.03% 0.27s 1.66% gitlab.com/kokizzu/gokil/Z.(*TemplateChain).Reload
0 0% 79.03% 0.24s 1.47% log.(*Logger).Output
0 0% 79.03% 0.52s 3.19% main.Test
0 0% 79.03% 0.46s 2.82% main.main
0 0% 79.03% 4.81s 29.49% net.(*Dialer).Dial
0 0% 79.03% 4.81s 29.49% net.(*Dialer).DialContext
0 0% 79.03% 0.36s 2.21% net.(*TCPListener).accept
0 0% 79.03% 0.58s 3.56% net.(*conn).Close
0 0% 79.03% 0.58s 3.56% net.(*netFD).Close
0 0% 79.03% 1.61s 9.87% net.(*netFD).Write
0 0% 79.03% 0.57s 3.49% net.(*netFD).decref
0 0% 79.03% 0.57s 3.49% net.(*netFD).destroy
0 0% 79.03% 4.65s 28.51% net.(*netFD).dial
0 0% 79.03% 0.10s 0.61% net.(*netFD).init
0 0% 79.03% 0.09s 0.55% net.(*pollDesc).close
0 0% 79.03% 4.81s 29.49% net.Dial
0 0% 79.03% 0.11s 0.67% net.accept
0 0% 79.03% 4.74s 29.06% net.dialSerial
0 0% 79.03% 4.71s 28.88% net.dialTCP
0 0% 79.03% 4.69s 28.76% net.internetSocket
0 0% 79.03% 4.69s 28.76% net.socket
0 0% 79.03% 0.26s 1.59% net/http.(*Cookie).String
0 0% 79.03% 0.46s 2.82% net/http.(*Server).ListenAndServe
0 0% 79.03% 0.46s 2.82% net/http.(*Server).Serve
0 0% 79.03% 0.18s 1.10% net/http.(*chunkWriter).Write
0 0% 79.03% 0.47s 2.88% net/http.(*conn).close
0 0% 79.03% 0.61s 3.74% net/http.(*conn).readRequest
0 0% 79.03% 0.47s 2.88% net/http.(*conn).serve.func1
0 0% 79.03% 0.10s 0.61% net/http.(*response).WriteHeader
0 0% 79.03% 0.46s 2.82% net/http.ListenAndServe
0 0% 79.03% 0.26s 1.59% net/http.SetCookie
0 0% 79.03% 0.40s 2.45% net/http.checkConnErrorWriter.Write
0 0% 79.03% 0.16s 0.98% net/textproto.(*Reader).ReadLine
0 0% 79.03% 0.16s 0.98% net/textproto.(*Reader).ReadMIMEHeader
0 0% 79.03% 0.12s 0.74% net/textproto.(*Reader).readLineSlice
0 0% 79.03% 0.20s 1.23% os.(*File).Write
0 0% 79.03% 0.20s 1.23% os.(*File).write
0 0% 79.03% 0.22s 1.35% os.Stat
0 0% 79.03% 0.17s 1.04% runtime.(*mcache).nextFree
0 0% 79.03% 0.11s 0.67% runtime.(*mcache).nextFree.func1
0 0% 79.03% 0.11s 0.67% runtime.(*mcache).refill
0 0% 79.03% 0.13s 0.8% runtime.Caller
0 0% 79.03% 0.30s 1.84% runtime._System
0 0% 79.03% 0.11s 0.67% runtime.callers
0 0% 79.03% 0.86s 5.27% runtime.copystack
0 0% 79.03% 0.14s 0.86% runtime.futexwakeup
0 0% 79.03% 0.20s 1.23% runtime.gcAssistAlloc.func1
0 0% 79.03% 1.07s 6.56% runtime.gcBgMarkWorker
0 0% 79.03% 0.09s 0.55% runtime.gcMarkDone
0 0% 79.03% 0.19s 1.16% runtime.gchelper
0 0% 79.03% 14s 85.84% runtime.goexit
0 0% 79.03% 0.16s 0.98% runtime.goexit0
0 0% 79.03% 0.46s 2.82% runtime.main
0 0% 79.03% 0.59s 3.62% runtime.markroot.func1
0 0% 79.03% 0.87s 5.33% runtime.mcall
0 0% 79.03% 0.13s 0.8% runtime.minit
0 0% 79.03% 0.26s 1.59% runtime.mstart
0 0% 79.03% 0.26s 1.59% runtime.mstart1
0 0% 79.03% 0.12s 0.74% runtime.notewakeup
0 0% 79.03% 0.32s 1.96% runtime.scanstack.func1
0 0% 79.03% 0.24s 1.47% runtime.slicebytetostring
0 0% 79.03% 0.35s 2.15% runtime.stopm
0 0% 79.03% 0.13s 0.8% runtime.sysmon
0 0% 79.03% 0.10s 0.61% syscall.Accept4
0 0% 79.03% 0.43s 2.64% syscall.Close
0 0% 79.03% 4.56s 27.96% syscall.Connect
0 0% 79.03% 0.57s 3.49% syscall.Read
0 0% 79.03% 0.21s 1.29% syscall.Stat
0 0% 79.03% 0.10s 0.61% syscall.accept4
0 0% 79.03% 4.56s 27.96% syscall.connect
0 0% 79.03% 1.66s 10.18% syscall.write
0 0% 79.03% 0.18s 1.10% time.Time.Format
点版http://pastie.org/10969011 you can generate the graph call on http://www.webgraphviz.com/
我有一个使用 Go (httprouter/gokil) 编写的 Web 应用程序服务器，当我使用 siege -b -t10s -c255 对其进行测试时，它显示如下（最佳分数）：
POST API (read only query to database, cache query result to RAM)
Transaction rate: 4251.38 trans/sec (local without proxy)
Transaction rate: 2082.11 trans/sec (local with proxy)
Transaction rate: 1806.63 trans/sec (test server)
GET Realistic (static file request, multiple URL)
Transaction rate: 4417.75 trans/sec (local without proxy)
Transaction rate: 1419.58 trans/sec (local with proxy)
Transaction rate: 234.73 trans/sec (test server)
Transaction Rate: 40.50 trans/sec (other external site that use gokil)
GET One static file (getting /js/jquery.js)
Transaction rate: 4166.83 trans/sec (local without proxy)
Transaction rate: 2531.79 trans/sec (local with proxy)
Transaction rate: 31.39 trans/sec (test server)
Transaction rate: 20.95 trans/sec (other external site that use gokil)
For comparison, hello world
Transaction rate: 13838.83 trans/sec (plain Go https://play.golang.org/p/y8rJ4ZkclD )
Transaction rate: 5420.79 trans/sec (local without proxy https://gitlab.com/kokizzu/gokil/tree/master/_example )
Transaction rate: 2701.12 trans/sec (local with proxy)
local 的规格是 i7-4772HQ，三星 850 SSD。
我使用的代理是caddy。我使用的数据库是用于存储会话的 PostgreSQL 和 Redis。 test server 与千兆连接在同一个网络上。
问题是，如何衡量每个请求的时间：哪个 function/line 代码导致了瓶颈？因为我看其他benchmark Go 可以实现70k到171k rps.
我试过这个 blog，但它显示：
$ cd $GOPATH/src/gitlab.com/kokizzu/gokil/_example
$ go build
$ go tool pprof —text ./test
parsing profile: unrecognized profile format
没关系，从 this blog post 找到了方法，我看错了例子。
只需在 main 函数开始时添加
defer profile.Start(profile.CPUProfile).Stop()。Import/Go得到
github.com/pkg/profile构建并 运行 程序，对其进行基准测试，退出程序，在行尾它会显示如下内容：
2016/11/24 18:41:24 profile: caught interrupt, stopping profiles 2016/11/24 18:41:24 profile: cpu profiling disabled, /tmp/profile627033993/cpu.pprof
- 运行 命令 pprof 命令
go tool pprof -text /tmp/profile627033993/cpu.pprof
它会显示这样的东西：
$ go tool pprof -text /tmp/profile627033993/cpu.pprof
12.89s of 16.31s total (79.03%)
Dropped 386 nodes (cum <= 0.08s)
flat flat% sum% cum cum%
7.26s 44.51% 44.51% 7.40s 45.37% syscall.Syscall
0.42s 2.58% 47.09% 0.62s 3.80% runtime.scanobject
0.38s 2.33% 49.42% 1.09s 6.68% runtime.mallocgc
0.32s 1.96% 51.38% 0.32s 1.96% runtime.memmove
0.27s 1.66% 53.03% 0.27s 1.66% runtime.futex
0.25s 1.53% 54.57% 1.21s 7.42% runtime.gentraceback
0.21s 1.29% 55.86% 0.59s 3.62% runtime.pcvalue
0.19s 1.16% 57.02% 0.19s 1.16% runtime.usleep
0.18s 1.10% 58.12% 0.18s 1.10% runtime.readvarint
0.15s 0.92% 59.04% 0.15s 0.92% runtime.heapBitsForObject
0.15s 0.92% 59.96% 0.15s 0.92% runtime.heapBitsSetType
0.14s 0.86% 60.82% 0.14s 0.86% runtime._ExternalCode
0.14s 0.86% 61.68% 0.14s 0.86% runtime.epollctl
0.13s 0.8% 62.48% 0.13s 0.8% runtime.rtsigprocmask
0.12s 0.74% 63.21% 0.16s 0.98% runtime.deferreturn
0.12s 0.74% 63.95% 0.17s 1.04% runtime.greyobject
0.12s 0.74% 64.68% 0.16s 0.98% syscall.Syscall6
0.11s 0.67% 65.36% 0.40s 2.45% runtime.adjustframe
0.11s 0.67% 66.03% 0.11s 0.67% runtime.adjustpointers
0.11s 0.67% 66.71% 0.11s 0.67% runtime.memclr
0.11s 0.67% 67.38% 0.29s 1.78% runtime.step
0.10s 0.61% 68.00% 1.53s 9.38% runtime.systemstack
0.07s 0.43% 68.42% 0.21s 1.29% runtime.mapassign1
0.07s 0.43% 68.85% 0.25s 1.53% runtime.rawstring
0.06s 0.37% 69.22% 0.17s 1.04% runtime.scanblock
0.06s 0.37% 69.59% 0.17s 1.04% time.Time.AppendFormat
0.05s 0.31% 69.90% 0.12s 0.74% runtime.casgstatus
0.05s 0.31% 70.20% 0.10s 0.61% runtime.lock
0.05s 0.31% 70.51% 0.56s 3.43% runtime.newobject
0.05s 0.31% 70.82% 0.18s 1.10% runtime.tracebackdefers
0.04s 0.25% 71.06% 0.75s 4.60% bufio.(*Reader).ReadSlice
0.04s 0.25% 71.31% 0.32s 1.96% fmt.(*pp).doPrintf
0.04s 0.25% 71.55% 7.22s 44.27% gitlab.com/kokizzu/gokil/W.LoadSession
0.04s 0.25% 71.80% 0.32s 1.96% runtime.scanframeworker
0.04s 0.25% 72.04% 0.12s 0.74% runtime.typedmemmove
0.03s 0.18% 72.23% 0.25s 1.53% fmt.(*pp).printArg
0.03s 0.18% 72.41% 0.47s 2.88% github.com/op/go-logging.(*stringFormatter).Format
0.03s 0.18% 72.59% 0.67s 4.11% net.(*netFD).Read
0.03s 0.18% 72.78% 12.43s 76.21% net/http.(*conn).serve
0.03s 0.18% 72.96% 0.11s 0.67% runtime.(*mcentral).cacheSpan
0.03s 0.18% 73.15% 0.10s 0.61% runtime.deferproc.func1
0.03s 0.18% 73.33% 0.10s 0.61% runtime.exitsyscall
0.03s 0.18% 73.51% 0.09s 0.55% runtime.makemap
0.03s 0.18% 73.70% 0.72s 4.41% runtime.markroot
0.03s 0.18% 73.88% 0.09s 0.55% runtime.runqgrab
0.02s 0.12% 74.00% 0.65s 3.99% github.com/garyburd/redigo/redis.(*conn).readLine
0.02s 0.12% 74.13% 0.78s 4.78% github.com/garyburd/redigo/redis.(*conn).readReply
0.02s 0.12% 74.25% 0.09s 0.55% github.com/garyburd/redigo/redis.(*conn).writeCommand
0.02s 0.12% 74.37% 0.39s 2.39% gitlab.com/kokizzu/gokil/Z.(*TemplateChain).Render
0.02s 0.12% 74.49% 1.28s 7.85% main.AuthFilter
0.02s 0.12% 74.62% 0.32s 1.96% net.(*netFD).accept
0.02s 0.12% 74.74% 4.74s 29.06% net.dialSingle
0.02s 0.12% 74.86% 0.11s 0.67% net/http.(*connReader).Read
0.02s 0.12% 74.98% 0.66s 4.05% net/http.(*response).finishRequest
0.02s 0.12% 75.11% 0.49s 3.00% net/http.readRequest
0.02s 0.12% 75.23% 0.10s 0.61% runtime.SetFinalizer
0.02s 0.12% 75.35% 0.10s 0.61% runtime.concatstrings
0.02s 0.12% 75.48% 0.68s 4.17% runtime.findrunnable
0.02s 0.12% 75.60% 0.27s 1.66% runtime.makeslice
0.02s 0.12% 75.72% 0.90s 5.52% runtime.morestack
0.02s 0.12% 75.84% 0.12s 0.74% runtime.newarray
0.02s 0.12% 75.97% 0.32s 1.96% runtime.pcdatavalue
0.02s 0.12% 76.09% 0.27s 1.66% runtime.rawstringtmp
0.02s 0.12% 76.21% 0.78s 4.78% runtime.schedule
0.02s 0.12% 76.33% 0.57s 3.49% syscall.read
0.01s 0.061% 76.39% 0.71s 4.35% bufio.(*Reader).fill
0.01s 0.061% 76.46% 1.82s 11.16% bufio.(*Writer).flush
0.01s 0.061% 76.52% 0.34s 2.08% fmt.Sprintf
0.01s 0.061% 76.58% 5.19s 31.82% github.com/garyburd/redigo/redis.(*Pool).get
0.01s 0.061% 76.64% 0.25s 1.53% github.com/garyburd/redigo/redis.(*Pool).put
0.01s 0.061% 76.70% 2.14s 13.12% github.com/garyburd/redigo/redis.(*conn).Do
0.01s 0.061% 76.76% 0.31s 1.90% github.com/garyburd/redigo/redis.(*pooledConnection).Close
0.01s 0.061% 76.82% 1.96s 12.02% github.com/garyburd/redigo/redis.(*pooledConnection).Do
0.01s 0.061% 76.89% 0.75s 4.60% github.com/op/go-logging.(*Logger).Notice
0.01s 0.061% 76.95% 0.74s 4.54% github.com/op/go-logging.(*backendFormatter).Log
0.01s 0.061% 77.01% 0.42s 2.58% gitlab.com/kokizzu/gokil/W.(*Context).Finish
0.01s 0.061% 77.07% 0.42s 2.58% gitlab.com/kokizzu/gokil/W.(*Context).Render
0.01s 0.061% 77.13% 10.37s 63.58% gitlab.com/kokizzu/gokil/W.(*Engine).ServeHTTP
0.01s 0.061% 77.19% 0.10s 0.61% gitlab.com/kokizzu/gokil/W.(*Session).parseIpAddr
0.01s 0.061% 77.25% 2.57s 15.76% gitlab.com/kokizzu/gokil/W.Logger
0.01s 0.061% 77.31% 0.37s 2.27% net.(*TCPListener).AcceptTCP
0.01s 0.061% 77.38% 0.68s 4.17% net.(*conn).Read
0.01s 0.061% 77.44% 1.62s 9.93% net.(*conn).Write
0.01s 0.061% 77.50% 4.62s 28.33% net.(*netFD).connect
0.01s 0.061% 77.56% 0.10s 0.61% net.(*pollDesc).init
0.01s 0.061% 77.62% 4.71s 28.88% net.doDialTCP
0.01s 0.061% 77.68% 0.09s 0.55% net.runtime_pollClose
0.01s 0.061% 77.74% 0.18s 1.10% net/http.(*chunkWriter).writeHeader
0.01s 0.061% 77.81% 10.38s 63.64% net/http.serverHandler.ServeHTTP
0.01s 0.061% 77.87% 0.43s 2.64% net/http.tcpKeepAliveListener.Accept
0.01s 0.061% 77.93% 0.14s 0.86% runtime.adjustdefers
0.01s 0.061% 77.99% 0.11s 0.67% runtime.callers.func1
0.01s 0.061% 78.05% 0.23s 1.41% runtime.convT2E
0.01s 0.061% 78.11% 0.12s 0.74% runtime.deferproc
0.01s 0.061% 78.17% 0.29s 1.78% runtime.funcspdelta
0.01s 0.061% 78.23% 0.14s 0.86% runtime.futexsleep
0.01s 0.061% 78.30% 0.24s 1.47% runtime.gcAssistAlloc
0.01s 0.061% 78.36% 1.18s 7.23% runtime.gcDrain
0.01s 0.061% 78.42% 0.20s 1.23% runtime.gcDrainN
0.01s 0.061% 78.48% 0.09s 0.55% runtime.gcMarkTermination
0.01s 0.061% 78.54% 0.10s 0.61% runtime.netpoll
0.01s 0.061% 78.60% 0.88s 5.40% runtime.newstack
0.01s 0.061% 78.66% 0.14s 0.86% runtime.notesleep
0.01s 0.061% 78.72% 0.64s 3.92% runtime.park_m
0.01s 0.061% 78.79% 0.10s 0.61% runtime.runqsteal
0.01s 0.061% 78.85% 0.59s 3.62% runtime.scang
0.01s 0.061% 78.91% 0.53s 3.25% runtime.scanstack
0.01s 0.061% 78.97% 0.14s 0.86% runtime.startm
0.01s 0.061% 79.03% 1.67s 10.24% syscall.Write
0 0% 79.03% 0.12s 0.74% bufio.(*Reader).ReadLine
0 0% 79.03% 1.82s 11.16% bufio.(*Writer).Flush
0 0% 79.03% 0.09s 0.55% bytes.(*Buffer).Write
0 0% 79.03% 0.14s 0.86% fmt.Fprintf
0 0% 79.03% 0.17s 1.04% github.com/fatih/color.(*Color).SprintfFunc.func1
0 0% 79.03% 0.17s 1.04% github.com/fatih/color.BlueString
0 0% 79.03% 0.17s 1.04% github.com/fatih/color.printString
0 0% 79.03% 5.21s 31.94% github.com/garyburd/redigo/redis.(*Pool).Get
0 0% 79.03% 0.17s 1.04% github.com/garyburd/redigo/redis.(*conn).Close
0 0% 79.03% 4.91s 30.10% github.com/garyburd/redigo/redis.(*xDialer).Dial
0 0% 79.03% 4.93s 30.23% github.com/garyburd/redigo/redis.Dial
0 0% 79.03% 0.73s 4.48% github.com/op/go-logging.(*LogBackend).Log
0 0% 79.03% 0.74s 4.54% github.com/op/go-logging.(*Logger).log
0 0% 79.03% 0.49s 3.00% github.com/op/go-logging.(*Record).Formatted
0 0% 79.03% 0.74s 4.54% github.com/op/go-logging.(*moduleLeveled).Log
0 0% 79.03% 0.46s 2.82% gitlab.com/kokizzu/gokil/W.(*Engine).StartServer
0 0% 79.03% 0.30s 1.84% gitlab.com/kokizzu/gokil/W.(*Session).Save
0 0% 79.03% 0.73s 4.48% gitlab.com/kokizzu/gokil/W.(*Session).Touch
0 0% 79.03% 5.16s 31.64% gitlab.com/kokizzu/gokil/W.InitSession.func1
0 0% 79.03% 1.32s 8.09% gitlab.com/kokizzu/gokil/W.Recover
0 0% 79.03% 0.73s 4.48% gitlab.com/kokizzu/gokil/W.Session.ShouldRenew
0 0% 79.03% 0.09s 0.55% gitlab.com/kokizzu/gokil/W.hashCookie
0 0% 79.03% 0.24s 1.47% gitlab.com/kokizzu/gokil/W.newSession
0 0% 79.03% 0.27s 1.66% gitlab.com/kokizzu/gokil/Z.(*TemplateChain).Reload
0 0% 79.03% 0.24s 1.47% log.(*Logger).Output
0 0% 79.03% 0.52s 3.19% main.Test
0 0% 79.03% 0.46s 2.82% main.main
0 0% 79.03% 4.81s 29.49% net.(*Dialer).Dial
0 0% 79.03% 4.81s 29.49% net.(*Dialer).DialContext
0 0% 79.03% 0.36s 2.21% net.(*TCPListener).accept
0 0% 79.03% 0.58s 3.56% net.(*conn).Close
0 0% 79.03% 0.58s 3.56% net.(*netFD).Close
0 0% 79.03% 1.61s 9.87% net.(*netFD).Write
0 0% 79.03% 0.57s 3.49% net.(*netFD).decref
0 0% 79.03% 0.57s 3.49% net.(*netFD).destroy
0 0% 79.03% 4.65s 28.51% net.(*netFD).dial
0 0% 79.03% 0.10s 0.61% net.(*netFD).init
0 0% 79.03% 0.09s 0.55% net.(*pollDesc).close
0 0% 79.03% 4.81s 29.49% net.Dial
0 0% 79.03% 0.11s 0.67% net.accept
0 0% 79.03% 4.74s 29.06% net.dialSerial
0 0% 79.03% 4.71s 28.88% net.dialTCP
0 0% 79.03% 4.69s 28.76% net.internetSocket
0 0% 79.03% 4.69s 28.76% net.socket
0 0% 79.03% 0.26s 1.59% net/http.(*Cookie).String
0 0% 79.03% 0.46s 2.82% net/http.(*Server).ListenAndServe
0 0% 79.03% 0.46s 2.82% net/http.(*Server).Serve
0 0% 79.03% 0.18s 1.10% net/http.(*chunkWriter).Write
0 0% 79.03% 0.47s 2.88% net/http.(*conn).close
0 0% 79.03% 0.61s 3.74% net/http.(*conn).readRequest
0 0% 79.03% 0.47s 2.88% net/http.(*conn).serve.func1
0 0% 79.03% 0.10s 0.61% net/http.(*response).WriteHeader
0 0% 79.03% 0.46s 2.82% net/http.ListenAndServe
0 0% 79.03% 0.26s 1.59% net/http.SetCookie
0 0% 79.03% 0.40s 2.45% net/http.checkConnErrorWriter.Write
0 0% 79.03% 0.16s 0.98% net/textproto.(*Reader).ReadLine
0 0% 79.03% 0.16s 0.98% net/textproto.(*Reader).ReadMIMEHeader
0 0% 79.03% 0.12s 0.74% net/textproto.(*Reader).readLineSlice
0 0% 79.03% 0.20s 1.23% os.(*File).Write
0 0% 79.03% 0.20s 1.23% os.(*File).write
0 0% 79.03% 0.22s 1.35% os.Stat
0 0% 79.03% 0.17s 1.04% runtime.(*mcache).nextFree
0 0% 79.03% 0.11s 0.67% runtime.(*mcache).nextFree.func1
0 0% 79.03% 0.11s 0.67% runtime.(*mcache).refill
0 0% 79.03% 0.13s 0.8% runtime.Caller
0 0% 79.03% 0.30s 1.84% runtime._System
0 0% 79.03% 0.11s 0.67% runtime.callers
0 0% 79.03% 0.86s 5.27% runtime.copystack
0 0% 79.03% 0.14s 0.86% runtime.futexwakeup
0 0% 79.03% 0.20s 1.23% runtime.gcAssistAlloc.func1
0 0% 79.03% 1.07s 6.56% runtime.gcBgMarkWorker
0 0% 79.03% 0.09s 0.55% runtime.gcMarkDone
0 0% 79.03% 0.19s 1.16% runtime.gchelper
0 0% 79.03% 14s 85.84% runtime.goexit
0 0% 79.03% 0.16s 0.98% runtime.goexit0
0 0% 79.03% 0.46s 2.82% runtime.main
0 0% 79.03% 0.59s 3.62% runtime.markroot.func1
0 0% 79.03% 0.87s 5.33% runtime.mcall
0 0% 79.03% 0.13s 0.8% runtime.minit
0 0% 79.03% 0.26s 1.59% runtime.mstart
0 0% 79.03% 0.26s 1.59% runtime.mstart1
0 0% 79.03% 0.12s 0.74% runtime.notewakeup
0 0% 79.03% 0.32s 1.96% runtime.scanstack.func1
0 0% 79.03% 0.24s 1.47% runtime.slicebytetostring
0 0% 79.03% 0.35s 2.15% runtime.stopm
0 0% 79.03% 0.13s 0.8% runtime.sysmon
0 0% 79.03% 0.10s 0.61% syscall.Accept4
0 0% 79.03% 0.43s 2.64% syscall.Close
0 0% 79.03% 4.56s 27.96% syscall.Connect
0 0% 79.03% 0.57s 3.49% syscall.Read
0 0% 79.03% 0.21s 1.29% syscall.Stat
0 0% 79.03% 0.10s 0.61% syscall.accept4
0 0% 79.03% 4.56s 27.96% syscall.connect
0 0% 79.03% 1.66s 10.18% syscall.write
0 0% 79.03% 0.18s 1.10% time.Time.Format
点版http://pastie.org/10969011 you can generate the graph call on http://www.webgraphviz.com/