Golang程序性能分析

前言

程序性能分析我相信是每個程序員都會遇到的問題，比如說一個程序的CPU為什么占用這么高？有沒有優化的空間？又比如程序出現了內存泄漏如何排查等等。如果是C++程序會借助於Google pprof c++ profile，java程序會依賴於jstack等工具，幸運的是Golang語言本身就集成了性能分析工具pprof包，可以有效的分析程序CPU，MEM，Metux等指標。其中還可以通過第三方圖形應用來更加直觀的顯示每個調用關系和指標占用情況。

 

演示環境

$ uname -a
Darwin 18.6.0 Darwin Kernel Version 18.6.0: Thu Apr 25 23:16:27 PDT 2019; root:xnu-4903.261.4~2/RELEASE_X86_64 x86_64

$ go version
go version go1.12.4 darwin/amd64

 

下面我直接用Golang pprof官方提供的示例來演示下CPU和MEM的分析方法，以及集成出圖工具后的各種效果。

 

CPU

var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to file")

func main() {
    flag.Parse()
    if *cpuprofile != "" {
        f, err := os.Create(*cpuprofile)
        if err != nil {
            log.Fatal(err)
        }
        pprof.StartCPUProfile(f)
        defer pprof.StopCPUProfile()
    }
    ...

程序定義了一個cpuprofile的文件，用於保存程序的cpu prof信息。StartCPUProfile方法會將信息輸出到cpuprofile文件中，程序退出前會調用StopCPUProfile方法，將緩存的信息一並（flush）刷到cpuprofile中。

$ go build havlak1.go
$ ./havlak1 -cpuprofile havlak1.prof 
# of loops: 76000 (including 1 artificial root node)
$ go tool pprof havlak1 havlak1.prof 
File: havlak1
Type: cpu
Time: Jun 18, 2019 at 3:52pm (CST)
Duration: 14.81s, Total samples = 19.20s (129.67%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top 10
Showing nodes accounting for 11090ms, 57.76% of 19200ms total
Dropped 105 nodes (cum <= 96ms)
Showing top 10 nodes out of 99
      flat  flat%   sum%        cum   cum%
    2250ms 11.72% 11.72%     2550ms 13.28%  runtime.mapaccess1_fast64
    1830ms  9.53% 21.25%     4760ms 24.79%  runtime.scanobject
    1470ms  7.66% 28.91%     9250ms 48.18%  main.FindLoops
    1040ms  5.42% 34.32%     1040ms  5.42%  runtime.memmove
     880ms  4.58% 38.91%     3420ms 17.81%  runtime.mallocgc
     840ms  4.38% 43.28%     2660ms 13.85%  main.DFS
     800ms  4.17% 47.45%     1990ms 10.36%  runtime.mapassign_fast64ptr
     790ms  4.11% 51.56%     1020ms  5.31%  runtime.findObject
     600ms  3.12% 54.69%      760ms  3.96%  runtime.heapBitsSetType
     590ms  3.07% 57.76%      600ms  3.12%  runtime.pageIndexOf  

輸出top 10 表示的是顯示最消耗cpu的10個函數調用。上述每列指標的含義為：

• flat 采樣時，該函數正在運行的次數*采樣頻率（10ms），記得到估算的函數“運行時間”。不包含等待子函數返回的時間。
• flat% flat/總采樣時間值，例如第一行的數據 2250ms/（19.2*1000）Total samples =11.72%。
• sum% 前面所有flat%的累加，所以第一行的sum%永遠都是等於flat%，第二行21.25%=11.72%+9.53%。
• cum  采樣時，該函數出現在調用堆棧的采樣時間。包含等待子函數返回的時間。
• cum% cum/總采樣時間值，例如第一行的數據 2550ms/（19.2*1000）Total samples =13.28%。

上述的文字比例顯示說實話沒有看出具體的調用關系，有沒有更好的圖形界面呢，答案是用web命令，前提是已經安裝了圖像處理軟件graphviz，否則會報錯：

 

(pprof) web
Failed to execute dot. Is Graphviz installed? Error: exec: "dot": executable file not found in $PATH
$ brew install graphviz
(pprof) web

輸入web命令后會自動喚起瀏覽器顯示調用關系的圖片：

 

 但是這樣全盤的調用關系老實將也是有點亂，可以通過--nodefraction=0.1把占用低於10%的關系不顯示，也可以可以通過web mapaccess1 來查看runtime mapaccess1_fast64的單條調用關系鏈，會更加的聚焦和清晰。

其實上面的圖形還是不夠直觀，最直觀的調用關系和占比圖是火焰圖，但是火焰圖需要依賴第三方火焰圖生成工具，不是golang pprof自帶的，步驟下：

• 安裝火焰圖生成工具 go-torch go get github.com/uber/go-torch
• 安裝火焰圖生成腳本 FlameGraph 進入到go-torch的bin路徑執行git clone https://github.com/brendangregg/FlameGraph.git，cd FlameGraph && mv * ../

u$ go-torch havlak1 havlak1.prof 
INFO[17:38:11] Run pprof command: go tool pprof -raw -seconds 30 havlak1 havlak1.prof
INFO[17:38:11] Writing svg to torch.svg

在執行命令的當前目錄下會生成一個torch.svg的文件，用瀏覽器打開如下：

 

從底往上是一層層調用關系，長方格的長度表示占比。所以說調用關系和占比一目了然。

程序優化了DFS函數后的占用情況：

(pprof) top 5 
Showing nodes accounting for 4410ms, 38.82% of 11360ms total
Dropped 83 nodes (cum <= 56.80ms)
Showing top 5 nodes out of 106
      flat  flat%   sum%        cum   cum%
    1230ms 10.83% 10.83%     3650ms 32.13%  runtime.scanobject
     950ms  8.36% 19.19%     5430ms 47.80%  main.FindLoops
     840ms  7.39% 26.58%      840ms  7.39%  runtime.memmove
     730ms  6.43% 33.01%     2680ms 23.59%  runtime.mallocgc
     660ms  5.81% 38.82%      810ms  7.13%  runtime.findObject
(pprof)

可以看出現在函數的主要消耗在內存的申請和回收上面（runtime.mallocgc）。為了找出為什么gc回收這么頻繁，我們必須先找出究竟是哪里在頻繁的申請內存。所以引入了下面的MEM章節。

MEM

var memprofile = flag.String("memprofile", "", "write memory profile to this file")
...

    FindHavlakLoops(cfgraph, lsgraph)
    if *memprofile != "" {
        f, err := os.Create(*memprofile)
        if err != nil {
            log.Fatal(err)
        }
        pprof.WriteHeapProfile(f)
        f.Close()
        return
    }

分析運行的結果：

$ go tool pprof havlak3 havlak3.prof 
File: havlak3
Type: inuse_space
Time: Jun 18, 2019 at 5:05pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top5
Showing nodes accounting for 34.51MB, 100% of 34.51MB total
Showing top 5 nodes out of 13
      flat  flat%   sum%        cum   cum%
      18MB 52.17% 52.17%       18MB 52.17%  main.NewBasicBlock
    9.72MB 28.16% 80.32%     9.72MB 28.16%  main.FindLoops
       3MB  8.69% 89.02%        3MB  8.69%  main.(*BasicBlock).AddOutEdge
    2.29MB  6.64% 95.65%    20.29MB 58.80%  main.(*CFG).CreateNode
    1.50MB  4.35%   100%     1.50MB  4.35%  main.(*BasicBlock).AddInEdge
(pprof) 

顯示具體的函數內部內存占用情況：

(pprof) list CreateNode
Total: 34.51MB
ROUTINE ======================== main.(*CFG).CreateNode in /Users/haiweilu/saas/src/awesomeProject/test/havlak3.go
    2.29MB    20.29MB (flat, cum) 58.80% of Total
         .          .     94:    }
         .          .     95:    if node != len(cfg.Blocks) {
         .          .     96:        println("oops", node, len(cfg.Blocks))
         .          .     97:        panic("wtf")
         .          .     98:    }
         .       18MB     99:    bblock := NewBasicBlock(node)
    2.29MB     2.29MB    100:    cfg.Blocks = append(cfg.Blocks, bblock)
         .          .    101:
         .          .    102:    if len(cfg.Blocks) == 1 {
         .          .    103:        cfg.Start = bblock
         .          .    104:    }
         .          .    105:
(pprof) list FindLoops
Total: 34.51MB
ROUTINE ======================== main.FindLoops in /Users/haiweilu/saas/src/awesomeProject/test/havlak3.go
    9.72MB     9.72MB (flat, cum) 28.16% of Total
         .          .    263:        return
         .          .    264:    }
         .          .    265:
         .          .    266:    size := cfgraph.NumNodes()
         .          .    267:
    1.97MB     1.97MB    268:    nonBackPreds := make([]map[int]bool, size)
    5.77MB     5.77MB    269:    backPreds := make([][]int, size)
         .          .    270:
    1.97MB     1.97MB    271:    number := make([]int, size)
         .          .    272:    header := make([]int, size, size)
         .          .    273:    types := make([]int, size, size)
         .          .    274:    last := make([]int, size, size)
         .          .    275:    nodes := make([]*UnionFindNode, size, size)
         .          .    276:
(pprof) 

可以看到程序又大量的臨時變量的創建和銷毀，導致了golang的gc機制頻繁觸發，從而導致CPU飆高。有gc機制的編程語言並不意味着可以忽略內存分配問題，這個問題的簡單解決是保存一個全局的成員變量，避免內存的頻繁申請和釋放。

在線debug

package main

import (
    "net/http"
    _ "net/http/pprof"
)

func main()  {
    http.ListenAndServe("localhost:6060", nil)
}

通過瀏覽器debug：

通過go tool debug：

go tool pprof http://localhost:6060/debug/pprof/profile   # 30-second CPU profile
go tool pprof http://localhost:6060/debug/pprof/heap      # heap profile
go tool pprof http://localhost:6060/debug/pprof/block     # goroutine blocking profile

總結

本文講解了go pprof包分析golang 程序 CPU和MEM的用法，其中包含文字界面，簡單的web圖形界面和火焰圖，其實pprof還可以分析程序的其他指標，更多的技能解鎖等待大家自行發現。 

參考

https://blog.golang.org/profiling-go-programs