Comment établir le profil golang Web App serveur

Question

J'ai un serveur d'application Web écrite en utilisant Go (httprouter/gokil), quand je le tester à l'aide siege -b -t10s -c255, il montre quelque chose comme ça (meilleur score):

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) 

Le les spécifications pour local est i7-4772HQ, Samsung 850 SSD. Le proxy que j'utilise est caddy. La base de données que j'utilise est PostgreSQL et Redis pour stocker des sessions. test server est sur le même réseau avec la connectivité gigabit. La question est, comment mesurer le calendrier de chaque demande: quelle fonction/ligne de code qui provoque le goulot d'étranglement? Parce que je regarde d'autres benchmark Go peut atteindre 70k à 171k RPS.

J'ai essayé ce blog, mais il montre:

$ cd $GOPATH/src/gitlab.com/kokizzu/gokil/_example 
$ go build 
$ go tool pprof —text ./test 
parsing profile: unrecognized profile format 

Answer 1

Nevermind a trouvé un moyen de this blog post, j'ai mal lu l'exemple.

1. Ajoutez simplement defer profile.Start(profile.CPUProfile).Stop() au démarrage de la fonction principale.

2. Import/Va chercher github.com/pkg/profile

3. Construire et exécuter le programme, le benchmark, quittez le programme, à la fin de la ligne, il montrerait quelque chose comme ceci:

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 

4. Exécutez la commande pprof commande go tool pprof -text /tmp/profile627033993/cpu.pprof

Il montrerait quelque chose comme ceci:

$ 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 

La version dot http://pastie.org/10969011 vous pouvez générer l'appel graphique http://www.webgraphviz.com/