3. Go 性能調優之 —— 性能測量和分析

原文連接: https://github.com/sxs2473/go...
本文使用 Creative Commons Attribution-ShareAlike 4.0 International 協議進行受權許可。

性能測量和分析

在先前的部分,咱們研究了對單個函數的基準測試,當您提早知道瓶頸在哪裏時,這是很是有用的。然而,你常常會發現本身處於提問的位置node

爲何這個程序要運行這麼長時間?

剖析整個程序,這對於回答諸如此類的高級問題很是有用。在本節中,咱們將使用Go內置的分析工具從內部研究程序的操做。git

pprof

咱們今天要講的第一個工具是 pprofpprof 來自於 Google Perf Tools ,自最先的公開發布以來,已經集成到 Go 運行時中。github

pprof 由兩部分組成:golang

  • runtime/pprof 每一個 Go 程序都內置的包
  • gotoolpprof 用於解析 profile 文件

pprof 支持好幾種類型的分析,咱們今天將討論其中的三種:web

  • CPU 分析
  • 內存分析
  • 阻塞分析
  • 鎖競爭分析

CPU 分析

CPU 分析是最多見的類型,也是最明顯的。數組

當啓用 CPU 分析時,運行時將每 10ms 中斷一次,並記錄當前運行的 goroutines 的棧跟蹤。網絡

一旦分析文件完成,咱們就能夠解析它以肯定運行時間最長的代碼路徑。併發

函數在分析文件中出現的次數越多,代碼路徑佔總運行時間的百分比就越多。app

內存分析

在進行堆分配時,內存分析會記錄調用棧跟蹤dom

棧分配被認爲是無成本的,而且在內存 profile 中不被追蹤

內存分析,就像 CPU 分析是基於樣本的同樣,默認狀況下,每 1000 個分配中有 1 個內存分析樣本。這個速率是能夠改變的。

因爲內存分析是基於樣本的,而且由於它也跟蹤尚沒被使用的分配,所以使用內存分析來肯定應用程序的總內存使用量是很困難的。

我的想法: 我不認爲內存分析對查找內存泄漏有用。有更好的方法來肯定應用程序使用了多少內存。咱們將在之後的文章中討論這些。

阻塞分析

阻塞分析很是獨特。

阻塞 profile 和 CPU profile 很是相似,但它記錄了 goroutine 等待共享資源所花費的時間。

這對於肯定應用程序中的併發瓶頸很是有用。

阻塞分析能夠向你展現大量 goroutine 什麼時候能夠取得進展可是被阻塞了。包括:

  • 在沒有緩衝的 channel 上發送或接收
  • 向已滿的 channel 發送,或從一個空 channel 接收
  • 試圖 Lock 一個已經被另外一個 goroutine 鎖定的 sync.Mutex

阻塞分析是一個很是專業的工具,在你認爲已經消除了全部 CPU 和內存使用瓶頸以前,不該該使用它。

互斥鎖分析

互斥鎖分析與阻塞分析相似,但只關注互斥鎖競爭致使延遲的操做。

一次一個 profile

profile 記錄是有成本的

profile 分析對程序性能有一種適度但可衡量的影響, 尤爲是在增長內存分析採樣率的狀況下。

大多數工具不會阻止你同時啓用多個 profile 。

但仍是不要一次啓用多個 profile 。

若是你同時啓用多個 profile,他們將觀察本身的互動並拋棄你的結果。

收集一個 profile

Go 運行時的分析接口存在於 runtime/pprof 包中。 runtime/pprof 是一個很是低級的工具,因爲歷史緣由,不一樣類型 profile 的接口並不統一。

正如咱們在前一節中所看到的,pprof 分析工具已經構建到 testing 包中,但有時,在testing.B基準測試的上下文中放置您想要分析的代碼是不方便或困難的,而且必須直接使用runtime/pprof API。

這裏有一個 small package,便於更容易地分析現有的程序。

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

咱們將在本節中使用這個 profile 包。晚些時候,咱們將直接使用runtime/pprof接口。

使用 pprof

解析使用 go pprof 子命令:

go tool pprof /path/to/your/profile

注意 : 若是你已經使用 Go 一段時間了,你可能會被告知pprof有兩個參數。從 Go 1.9 開始,profile 文件包含展現 profile 所需的全部信息。你再也不須要生成 profile 的二進制文件了。  🎉

進一步閱讀

CPU 分析 - 例1

咱們寫一個程序來計算單詞數量:

package main

import (
        "fmt"
        "io"
        "log"
        "os"
        "unicode"
)

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

func main() {
        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
        for {
                r, err := readbyte(f)
                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)
}

讓咱們看看赫爾曼·梅爾維爾的經典《白鯨記》 (源自古騰堡計劃)中有多少單詞。

% time go run main.go moby.txt
"moby.txt": 181275 words

real    0m2.110s
user    0m1.264s
sys     0m0.944s

來和 unix 系統的 wc -w 作一個比較

% time wc -w  moby.txt
  215829 moby.txt

real    0m0.012s
user    0m0.009s
sys     0m0.002s

結果不同。wc 給出的字數高出 19% 左右,由於它計算一個詞的規則與個人例子不一樣。這並不重要——兩個程序都將整個文件做爲輸入,並在一次傳遞中計算從單詞到非單詞的轉換次數。

讓咱們使用 pprof 調查這些程序爲什麼具備不一樣的運行時間。

加入 CPU 分析

首先,編輯 main.go 並開啓 profile

...
        "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

如今咱們可用用 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 命令從降序展現了函數的調用時間。 咱們能夠看到在 syscall.Syscall上花費了 99% 的時間, 和 main.readbyte花費了不多的一部分。

咱們還可使用web命令可視化這個調用。這將從 profile 數據生成有向圖。它實際使用來自 Graphviz 的dot命令。

圖片描述

在圖中,消耗 CPU 時間最多的盒子是最大的 -- 咱們看到的sys call.Syscall 佔用了總程序運行時間的 99.3%。通往syscall.Syscall的一串盒子表明它的直接調用者 -- 若是多個路徑收斂於同一個函數,則表示有多個調用者。箭頭旁邊的數字表示運行所花費的時間。咱們從 main.readbyte 開始看,一直到最後,佔用都接近0。

改進咱們的版本

咱們程序跑慢不是由於 Go 的 syscall.Syscall 。由於系統調用原本就慢。

每次調用readbyte都會產生一個緩衝區大小爲1的syscall.Read。所以,咱們程序執行的系統調用數等於輸入的大小。在 pprof 圖中咱們能夠看到,讀取輸入決定了其餘一切。

func main() {
        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來提高性能。

內存分析

words profile 還告訴了咱們,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 -- 這並不複雜,只有三行代碼:

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

咱們將在下一節詳細討論爲何會發生這種狀況,但目前咱們看到的是,每一個對readbyte的調用都在分配一個新的1字節長的數組,而這個數組正在堆上分配。

分配對象 vs. 使用中的對象

內存分析有兩種選擇,以 go tool pprof 工具的標識命名:

  • -alloc_objects 報告每次分配時的所在的地方
  • -inuse_objects 報告被使用的地方,能夠在 profile 文件的末尾找到

爲了說明這一點,這裏有一個設計好的程序,它將以一種受控的方式分配一些內存。

// ensure y is live beyond the end of main.
var y []byte

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

// allocate allocates count byte slices and returns the first slice allocated.
func allocate(count int) []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(1<<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

讓咱們看一下分配對象的圖,這是默認值,並顯示了致使 profile 文件中每一個對象分配的調用圖。

% go tool pprof -web -alloc_objects /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile891268605/mem.pprof

圖片描述
不足爲奇的是超過 99% 的分配都是在 makeByteSlice內部進行的。如今讓咱們 換用-inuse_objects查看 profile

% go tool pprof -web -inuse_objects /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile891268605/mem.pprof

圖片描述
咱們看到的不是在 profile 期間分配的對象,而是在 profile 獲取時仍在使用的對象——這忽略了垃圾收集器回收的對象的堆棧跟蹤。

阻塞分析 - 例1

咱們將展現最後一種分析 - 阻塞分析。咱們使用 net/http包中ClientServer的基準測試。

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

圖片描述

幀指針

Go 1.7 已經發布,而且與 amd64 的新編譯器一塊兒,編譯器如今默認啓用幀指針。

幀指針是一個始終指向當前棧幀頂部的寄存器。

它支持使用 gdb(1)perf(1) 等工具解析 Go 調用棧

詳情能夠參考下面的擴展閱讀

進一步閱讀:

相關文章
相關標籤/搜索