Go 高效能系列教程之二：效能評估和分析

yudotyang發表於2021-05-28
Go

在上一節中，我們研究了對單個函式進行基準測試，這個的使用場景是在你已經提前知道瓶頸在哪裡時很有用。

但是，通常你會發現你並不知道效能瓶頸在哪裡，你經常會問：

程式為什麼耗時這麼久？

對於上面的問題，我們需要對整個程式進行概要分析以找出程式的瓶頸在哪裡。本節，我們講使用 Go 的內建效能分析工具 pprof 從內部檢視程式的整體執行情況。

2.1 pprof

今天我們要討論的第一個工具是 pprof. pprof誕生自 Google Perf Tools 工具套件，並且已經整合到 Go 執行時環境中。

pprof由兩部分組成：

  • runtime/pprof 執行時包。
  • go tool pprof 工具。用於分析效能。

2.2 效能型別

pprof 支援以下型別的效能分析：

  • CPU 效能分析
  • 記憶體效能分析
  • 阻塞效能分析
  • 互斥&競爭分析

2.2.1 CPU 效能分析（CPU profiling）

CPU 效能分析是最常用、最明確的效能分析。 當 CPU 效能分析啟用的時候，執行時環境會每 10 毫秒中斷一次並記錄下當前執行協程的堆疊跟蹤資訊。

一旦效能分析完成，我們就可以分析並找出執行耗時最長的程式碼路徑。一個函式在效能分析中出現的次數越多，則其所在的程式碼路徑花費的時間就越長。

2.2.2 記憶體效能分析（Memory profiling）

記憶體效能分析記錄了堆記憶體分配的呼叫棧資訊。棧記憶體分配的耗時可以忽略不計，所以不計入到記憶體效能分析中。

和 CPU 資料採集類似，記憶體資料採集預設是每分配 1000 次則取樣一次。 由於記憶體資料採集是基於取樣的，並且由於它跟蹤的是未使用的分配，因此該技術很難確定應用程式的整體記憶體使用情況。

個人觀點：我並沒有發現記憶體分析對找到記憶體峰值有用。稍後我們將介紹一些較好的方式用來檢視到應用程式整體使用記憶體情況。

2.2.3 阻塞效能分析（Blocking profiling）

阻塞分析是 Go 中獨有的。 一個阻塞分析類似於 CPU 的效能分析，但是它記錄的是一個協程花在等待共享資源上的時間。

這對於分析併發瓶頸非常有用。

阻塞分析可以顯示出大量 goroutine 何時可以取得進展，但不阻止了。阻塞包括：

  • 向一個非快取的通道（unbuffered channel）上傳送或接收資料
  • 向一個已滿的通道傳送資料，或從一個空通道上接收資料
  • 試圖給一個互斥資源加鎖，而該互斥資源已經被另一個協程佔用。

阻塞分析是一個非常特殊的工具，你應該首先解決你的 CPU、記憶體瓶頸之後，再來分析阻塞效能。

2.2.4 互斥效能分析

互斥分析類似於阻塞分析，但是它主要關注在導致互斥鎖徵用導致延遲的操作上。

互斥分析不能提供給你該程式將要執行多長時間，以及已經執行了多長時間。相反，它能夠記錄該程式在等待互斥鎖上花費了多長時間。就像阻塞分析，它指出的是在等待資源上花費了多長時間。

換句話說，就是如果互斥競爭被移除，那麼會節省多少時間。

2.3 一次只做一類效能分析

效能分析並不是沒有成本的。

效能分析對程式是有一定的影響的，尤其是當你增加了記憶體分析取樣頻率的時候。

大多數工具不會阻止你一次啟用多個效能分析。

注意：不要一次啟用多個型別的效能分析 如果你一次啟用多個型別的效能分析，每個型別的只會關注自己的互動並且會丟掉其他的結果。

2.4 採集效能概況資料

Go 語言的執行時效能採集介面在 runtime/pprof 包下。runtime/pprof 是比較低層的工具，並且由於歷史原因，不同型別的效能概況收集介面也不統一。

正如我們上面看到的，pprof 概況收集是 testing 包中內建的，但有時將你要分析的程式碼放在 test.B 基準測試環境中會帶來不變或困難，並且必須直接使用 runtime/pprof 的 API。

幾年前，我寫了一個小工具，來使它變得更容易一些.

import "github.com/pkg/profile"func main() {    defer profile.Start().Stop()    //...}

在上面這段程式碼中，我們使用了 profile 包。稍後我們將直接使用 runtime/pprof 介面。

2.5 利用 pprof 分析一個測量檔案

到目前為止，我們已經討論了 pprof 功能能夠評估什麼，並且如何產生一個評估概要檔案，接下來讓我們討論使用 pprof 工具如何分析一個評估概要檔案。

通過以下命令分析概要評估檔案的內容：

go tool pprof /path/to/your/profile

該工具提供了分析資料的幾種不同形式：文字、圖表以及火焰圖。

如果你已經用過 Go 一段時間了，你可能已經被告知說 pprof 會使用兩個引數。從 Go 1.9 開始，概要檔案包含了概要分析所有的資訊。你不再需要單獨生成概要分析檔案了。

2.5.1 進一步閱讀

2.5.2 CPU 效能分析（練習）

讓我寫一段統計單詞的程式碼：

package main

import (    
    "bufio"
    "fmt"
    "io"
    "log"
    "os"
    "unicode"
    "github.com/pkg/profile"
)

func readbyte(r io.Reader) (rune, error) {
    var buf [1]byte 
    _, err := r.Read(buf[:])
    return rune(buf[0]), err
}

func main() {   
    defer profile.Start(profile.CPUProfile, profile.ProfilePath(".")).Stop()        
    f, err := os.Open(os.Args[1])   
    if err != nil {
        log.Fatalf("could not open file %q:%v", os.Args[1], err)    
    }

    words := 0  
    inword := false 
    b := bufio.NewReader(f) 

    for {       
        r, err := readbyte(b)       
        if err == io.EOF {          
            break       
        }               
        if err != nil {         
            log.Fatalf("could not read file %q:%v", os.Args[1], err)        
        }       

        if unicode.IsSapce(r) && inword {
        words++         
        inword = false      
    }       

    inword = unicode.IsLetter(r)    
    }

    fmt.Printf("%q:%d words\n", os.Args[1], words)}

讓我們看看在 moby.txt 檔案中有多少個單詞：

% go build && time ./words moby.txt
"moby.txt": 181275 words
real    0m2.110
suser    0m1.264
ssys     0m0.944s

和 unix 的 wc -w 命令比較一下：

% time wc -w moby.txt
215829 moby.txt
real    0m0.012
suser    0m0.009
ssys     0m0.002s

由此可知，統計的單詞數量不一樣。wc 工具多出了 19%，因為它對於一個單詞的識別規則和我的程式是不一樣的。這不重要 -- 兩個程式都將整個檔案作為輸入，並在一次過程中計算從單詞到非單詞的轉換次數。

讓我們研究一下為什麼使用 pprof 工具的程式執行時間會有不同。

2.5.3 新增 CPU 測量分析

首先，編輯 main.go 檔案並開啟 profiling

import (
        "github.com/pkg/profile"
)

func main() {
        defer profile.Start().Stop()
        // ...

現在當我們執行該程式的時候，一個 cpu.pprof 檔案被建立。

% go run main.go moby.txt
2018/08/25 14:09:01 profile: cpu profiling enabled, /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile239941020/cpu.pprof
"moby.txt": 181275 words
2018/08/25 14:09:03 profile: cpu profiling disabled, /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile239941020/cpu.pprof

現在，我們得到了 cpu.pprof 檔案，並且可以用 go tool pprof 命令進行分析

% go tool pprof /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile239941020/cpu.pprof
Type: cpu
Time: Aug 25, 2018 at 2:09pm (AEST)
Duration: 2.05s, Total samples = 1.36s (66.29%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 1.42s, 100% of 1.42s total
      flat  flat%   sum%        cum   cum%
     1.41s 99.30% 99.30%      1.41s 99.30%  syscall.Syscall
     0.01s   0.7%   100%      1.42s   100%  main.readbyte
         0     0%   100%      1.41s 99.30%  internal/poll.(*FD).Read
         0     0%   100%      1.42s   100%  main.main
         0     0%   100%      1.41s 99.30%  os.(*File).Read
         0     0%   100%      1.41s 99.30%  os.(*File).read
         0     0%   100%      1.42s   100%  runtime.main
         0     0%   100%      1.41s 99.30%  syscall.Read
         0     0%   100%      1.41s 99.30%  syscall.read

top 命令是最常用的一個命令。從上面的結果得知，99% 的時間化在了 *syscall.Syscall 函式上，只有一小部分時間花在了 main.readbyte 函式上。

我們還可以使用 web 命令對結果視覺化。這會將 profile 中的資料直接圖形化。

然而，在 Go1.10 及其以後的版本中，Go 在本機上自帶了支援 http 伺服器的 pprof 版本。

% go  tool pprof -http=:8080 /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile239941020/cpu.pprof

該命令將開啟一個 web 瀏覽器：

  • 圖形化模式
  • 火焰圖模式

在影像化模式下，最大的那個盒子花費的 cpu 時間越多 --- 我們看到 syscall.SysCall 的花費時間佔了整個程式的 99.3%。盒子上指向 syscall.Syscall 的字串代表直接呼叫者 --- 如果多個程式碼路徑都覆蓋同一個函式，則可以有多個。箭頭的大小代表在一個盒子的子容器中花費了多少時間，我們看到 main.readbyte 所花費的時間接近 0 秒。

問題：為什麼我們的程式比 wc 命令這麼慢嗎？

2.5.4 改進我們的程式

我們程式慢的原因不是因為 Go 的 syscall.Syscall 慢。那是因為系統呼叫通常是昂貴的操作。

每次對 readbyte 的呼叫都會導致一次緩衝區大小為 1 的 syscall.Read 操作。所以我們的程式執行 syscall 的數量等於輸入的大小。在 pprof 圖中我們可以看到，讀取輸入的內容佔了主導地位。

func main() {
    defer profile.Start(profile.MemProfile, profile.MemProfileRate(1)).Stop()
    // defer profile.Start(profile.MemProfile).Stop()

    f, err := os.Open(os.Args[1])
    if err != nil {
        log.Fatalf("could not open file %q: %v", os.Args[1], err)
    }

    b := bufio.NewReader(f)
    words := 0
    inword := false
    for {
        r, err := readbyte(b)
        if err == io.EOF {
            break
        }
        if err != nil {
            log.Fatalf("could not read file %q: %v", os.Args[1], err)
        }
        if unicode.IsSpace(r) && inword {
            words++
            inword = false
        }
        inword = unicode.IsLetter(r)
    }
    fmt.Printf("%q: %d words\n", os.Args[1], words)
}

通過在輸入檔案和 readbyte 之間插入一個 bufio.Reader, 然後將該版本的花費時間和 wc 相比。他們是不是非常的接近了?

2.5.5 記憶體測量

新的 words 分析中表明 readbyte 函式內部正在分配某些內容。我們可使用 pprof 進行研究：

defer profile.Start(profile.MemProfile).Stop()

然後執行該程式：

% go run main2.go moby.txt
2018/08/25 14:41:15 profile: memory profiling enabled (rate 4096), /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile312088211/mem.pprof
"moby.txt": 181275 words
2018/08/25 14:41:15 profile: memory profiling disabled, /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile312088211/mem.pprof

圖片一：

正如我們懷疑的是記憶體分配是從 readbyte 分配的-readbyte 函式並不是那麼複雜，只有三行：

使用 pprof 確定記憶體分配來自哪裡。

func readbyte(r io.Reader) (rune, error) {
        var buf [1]byte 
        _, err := r.Read(buf[:])
        return rune(buf[0]), err
}

注：記憶體分配來自於 var buf [1] byte 這一行程式碼。

我們會在下一節更詳細的討論在此發生記憶體分配的原因，但我們現在看到的是每次呼叫 readbyte 函式，都會在堆上分配一個 1 位元組的陣列。

有哪些方法可以避免這樣分配？試一試並通過用 cpu 和記憶體分析法來證明它。

2.5.6 分配物件 VS 重用物件

記憶體分析中有兩個變體，在 go tool pprof 標誌中通過引數命名可以體現。

  • -alloc_objects 報告在哪些地方分配了記憶體
  • -inuse_objects 當記憶體資料收集結束後，報告哪些地方還在使用記憶體

為了說明這一點，這是一個人為設計的程式，它將以受控方式分配一堆記憶體。

const count = 100000

var y []byte

func main() {
    defer profile.Start(profile.MemProfile, profile.MemProfileRate(1)).Stop()
    y = allocate()
    runtime.GC()
}

// allocate allocates count byte slices and returns the first slice allocated.
func allocate() []byte {
    var x [][]byte
    for i := 0; i < count; i++ {
        x = append(x, makeByteSlice())
    }
    return x[0]
}

// makeByteSlice returns a byte slice of a random length in the range [0, 16384).
func makeByteSlice() []byte {
    return make([]byte, rand.Intn(2^14))
}

該程式是 profile 包的註釋，我們將記憶體監控的速率設定為 1，即記錄每次分配的堆疊跟蹤。 這會大大減慢該程式的速度，但是您很快就會知道原因。

% go run main.go
2018/08/25 15:22:05 profile: memory profiling enabled (rate 1), /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile730812803/mem.pprof
2018/08/25 15:22:05 profile: memory profiling disabled, /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile730812803/mem.pprof

讓我們看下分配物件的圖表，這是預設的，顯示了在記憶體監控期間導致每個物件記憶體分配的呼叫過程。

% go tool pprof -http=:8080 /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile891268605/mem.pprof

不用驚訝，超過 99% 的記憶體是在 makeByteSlice 函式中分配的。接下來讓我們使用-inuse_objects 引數來看一下：

% go tool pprof -http=:8080 /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile891268605/mem.pprof

我們看到的不是在記憶體監控期間分配的物件，而是在獲取監控時仍在使用的物件 - 這將忽略已由垃圾收集器回收的物件的堆疊跟蹤。

2.5.7 阻塞測量

最後一個監控型別是阻塞監控。我們將使用 net/http 包下的 ClientServer 的基準測試：

% go test -run=XXX -bench=ClientServer$ -blockprofile=/tmp/block.p net/http% go tool pprof -http=:8080 /tmp/block.p

2.5.8 互斥測量

互斥爭用隨著 goroutine 的數量而增加。

type AtomicVariable struct {
    mu  sync.Mutex
    val uint64
}

func (av *AtomicVariable) Inc() {
    av.mu.Lock()
    av.val++
    av.mu.Unlock()
}

func BenchmarkInc(b *testing.B) {
    var av AtomicVariable

    b.RunParallel(func(pb *testing.PB) {
        pb.ResetTimer()
        for pb.Next() {
            av.Inc()
        }
    })
}

按如下命令執行：

% go test -bench=. -cpu=1,2,4,8,16 ./examples/mutex

2.5.9 擴充套件閱讀

原文連結 https://dave.cheney.net/high-performance-go-workshop/gophercon-2019.html#benchmarking

更多原創文章乾貨分享，請關注公眾號
  • Go 高效能系列教程之二：效能評估和分析
  • 加微信實戰群請加微信(註明:實戰群)：gocnio

相關文章