1. 首頁
  2. 問答
  3. 如何分析Golang Web應用程序服務器

如何分析Golang Web應用程序服務器

2016-11-24 126 views
2

我有使用Go（httprouter/gokil），當我使用siege -b -t10s -c255測試它，它顯示了這樣的事情（最好成績）編寫的Web應用程序服務器：如何分析Golang Web應用程序服務器

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位於與千兆位連接相同的網絡上。

問題是，如何衡量每個請求的時間：導致瓶頸的哪個函數/哪行代碼？因爲我看看其他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

來源

2016-11-24 Kokizzu

回答

2

沒關係，找到了一種方法，從this blog post，我誤解的例子。

  1. 只需在主功能啓動時添加defer profile.Start(profile.CPUProfile).Stop()即可。

  2. 導入/去拿github.com/pkg/profile

  3. 生成並運行該程序，基準它，退出程序，在該行的最後它會顯示這樣的事情：

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您可以生成http://www.webgraphviz.com/

    圖形通話

    來源

    2016-11-24 11:46:04 Kokizzu

    相關問題

     相關問題