13.10 性能調(diào)試：分析并優(yōu)化 Go 程序

13.10.1 時(shí)間和內(nèi)存消耗

可以用這個(gè)便捷腳本 xtime 來測(cè)量：

#!/bin/sh
/usr/bin/time -f '%Uu %Ss %er %MkB %C' "$@"

在 Unix 命令行中像這樣使用 xtime goprogexec，這里的 progexec 是一個(gè) Go 可執(zhí)行程序，這句命令行輸出類似：56.63u 0.26s 56.92r 1642640kB progexec，分別對(duì)應(yīng)用戶時(shí)間，系統(tǒng)時(shí)間，實(shí)際時(shí)間和最大內(nèi)存占用。

13.10.2 用 go test 調(diào)試

如果代碼使用了 Go 中 testing 包的基準(zhǔn)測(cè)試功能，我們可以用 gotest 標(biāo)準(zhǔn)的 -cpuprofile 和 -memprofile 標(biāo)志向指定文件寫入 CPU 或 內(nèi)存使用情況報(bào)告。

使用方式：go test -x -v -cpuprofile=prof.out -file x_test.go

編譯執(zhí)行 x_test.go 中的測(cè)試，并向 prof.out 文件中寫入 cpu 性能分析信息。

13.10.3 用 pprof 調(diào)試

你可以在單機(jī)程序 progexec 中引入 runtime/pprof 包；這個(gè)包以 pprof 可視化工具需要的格式寫入運(yùn)行時(shí)報(bào)告數(shù)據(jù)。對(duì)于 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()
    }
...

代碼定義了一個(gè)名為 cpuprofile 的 flag，調(diào)用 Go flag 庫來解析命令行 flag，如果命令行設(shè)置了 cpuprofile flag，則開始 CPU 性能分析并把結(jié)果重定向到那個(gè)文件。（os.Create 用拿到的名字創(chuàng)建了用來寫入分析數(shù)據(jù)的文件）。這個(gè)分析程序最后需要在程序退出之前調(diào)用 StopCPUProfile 來刷新掛起的寫操作到文件中；我們用 defer 來保證這一切會(huì)在 main 返回時(shí)觸發(fā)。

現(xiàn)在用這個(gè) flag 運(yùn)行程序：progexec -cpuprofile=progexec.prof

然后可以像這樣用 gopprof 工具：gopprof progexec progexec.prof

gopprof 程序是 Google pprofC++ 分析器的一個(gè)輕微變種；關(guān)于此工具更多的信息，參見https://github.com/gperftools/gperftools。

如果開啟了 CPU 性能分析，Go 程序會(huì)以大約每秒 100 次的頻率阻塞，并記錄當(dāng)前執(zhí)行的 goroutine 棧上的程序計(jì)數(shù)器樣本。

此工具一些有趣的命令：

1）topN

用來展示分析結(jié)果中最開頭的 N 份樣本，例如：top5 它會(huì)展示在程序運(yùn)行期間調(diào)用最頻繁的 5 個(gè)函數(shù)，輸出如下：

Total: 3099 samples
626 20.2% 20.2% 626 20.2% scanblock
309 10.0% 30.2% 2839 91.6% main.FindLoops
...

第 5 列表示函數(shù)的調(diào)用頻度。

2）web 或 web 函數(shù)名

該命令生成一份 SVG 格式的分析數(shù)據(jù)圖表，并在網(wǎng)絡(luò)瀏覽器中打開它（還有一個(gè) gv 命令可以生成 PostScript 格式的數(shù)據(jù)，并在 GhostView 中打開，這個(gè)命令需要安裝 graphviz）。函數(shù)被表示成不同的矩形（被調(diào)用越多，矩形越大），箭頭指示函數(shù)調(diào)用鏈。

3）list 函數(shù)名 或 weblist 函數(shù)名

展示對(duì)應(yīng)函數(shù)名的代碼行列表，第 2 列表示當(dāng)前行執(zhí)行消耗的時(shí)間，這樣就很好地指出了運(yùn)行過程中消耗最大的代碼。

如果發(fā)現(xiàn)函數(shù) runtime.mallocgc（分配內(nèi)存并執(zhí)行周期性的垃圾回收）調(diào)用頻繁，那么是應(yīng)該進(jìn)行內(nèi)存分析的時(shí)候了。找出垃圾回收頻繁執(zhí)行的原因，和內(nèi)存大量分配的根源。

為了做到這一點(diǎn)必須在合適的地方添加下面的代碼：

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

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

用 -memprofile flag 運(yùn)行這個(gè)程序：progexec -memprofile=progexec.mprof

然后你可以像這樣再次使用 gopprof 工具：gopprof progexec progexec.mprof

top5，list 函數(shù)名 等命令同樣適用，只不過現(xiàn)在是以 Mb 為單位測(cè)量內(nèi)存分配情況，這是 top 命令輸出的例子：

Total: 118.3 MB
    66.1 55.8% 55.8% 103.7 87.7% main.FindLoops
    30.5 25.8% 81.6% 30.5 25.8% main.*LSG·NewLoop
    ...

從第 1 列可以看出，最上面的函數(shù)占用了最多的內(nèi)存。

同樣有一個(gè)報(bào)告內(nèi)存分配計(jì)數(shù)的有趣工具：

gopprof --inuse_objects progexec progexec.mprof

對(duì)于 web 應(yīng)用來說，有標(biāo)準(zhǔn)的 HTTP 接口可以分析數(shù)據(jù)。在 HTTP 服務(wù)中添加

import _ "http/pprof"

會(huì)為 /debug/pprof/ 下的一些 URL 安裝處理器。然后你可以用一個(gè)唯一的參數(shù)——你服務(wù)中的分析數(shù)據(jù)的 URL 來執(zhí)行 gopprof 命令——它會(huì)下載并執(zhí)行在線分析。

gopprof http://localhost:6060/debug/pprof/profile # 30-second CPU profile
gopprof http://localhost:6060/debug/pprof/heap # heap profile

在 Go-blog（引用 15）中有一篇很好的文章用具體的例子進(jìn)行了分析：分析 Go 程序（2011年6月）。

鏈接

• 目錄
• 上一節(jié)：用（測(cè)試數(shù)據(jù)）表驅(qū)動(dòng)測(cè)試
• 下一章：協(xié)程（goroutine）與通道（channel）