go tool pprof

starkbl發表於2021-09-09


我們可以使用go tool pprof命令來互動式的訪問概要檔案的內容。命令將會分析指定的概要檔案,並會根據我們的要求為我們提供高可讀性的輸出資訊。

在Go語言中,我們可以透過標準庫的程式碼包runtime和runtime/pprof中的程式來生成三種包含實時性資料的概要檔案,分別是CPU概要檔案、記憶體概要檔案和程式阻塞概要檔案。下面我們先來分別介紹用於生成這三種概要檔案的API的用法。

CPU概要檔案

在介紹CPU概要檔案的生成方法之前,我們先來簡單瞭解一下CPU主頻。CPU的主頻,即CPU核心工作的時脈頻率(CPU Clock Speed)。CPU的主頻的基本單位是赫茲(Hz),但更多的是以兆赫茲(MHz)或吉赫茲(GHz)為單位。時脈頻率的倒數即為時鐘週期。時鐘週期的基本單位為秒(s),但更多的是以毫秒(ms)、微妙(us)或納秒(ns)為單位。在一個時鐘週期內,CPU執行一條運算指令。也就是說,在1000 Hz的CPU主頻下,每1毫秒可以執行一條CPU運算指令。在1 MHz的CPU主頻下,每1微妙可以執行一條CPU運算指令。而在1 GHz的CPU主頻下,每1納秒可以執行一條CPU運算指令。

在預設情況下,Go語言的執行時系統會以100 Hz的的頻率對CPU使用情況進行取樣。也就是說每秒取樣100次,即每10毫秒會取樣一次。為什麼使用這個頻率呢?因為100 Hz既足夠產生有用的資料,又不至於讓系統產生停頓。並且100這個數上也很容易做換算,比如把總取樣計數換算為每秒的取樣數。實際上,這裡所說的對CPU使用情況的取樣就是對當前的Goroutine的堆疊上的程式計數器的取樣。由此,我們就可以從樣本記錄中分析出哪些程式碼是計算時間最長或者說最耗CPU資源的部分了。我們可以透過以下程式碼啟動對CPU使用情況的記錄。

func startCPUProfile() {     if *cpuProfile != "" {         f, err := os.Create(*cpuProfile)         if err != nil {             fmt.Fprintf(os.Stderr, "Can not create cpu profile output file: %s",                 err)             return         }         if err := pprof.StartCPUProfile(f); err != nil {             fmt.Fprintf(os.Stderr, "Can not start cpu profile: %s", err)             f.Close()             return         }     } }

在函式startCPUProfile中,我們首先建立了一個用於存放CPU使用情況記錄的檔案。這個檔案就是CPU概要檔案,其絕對路徑由*cpuProfile的值表示。然後,我們把這個檔案的例項作為引數傳入到函式`pprof.StartCPUProfile中。如果此函式沒有返回錯誤,就說明記錄操作已經開始。需要注意的是,只有CPU概要檔案的絕對路徑有效時此函式才會開啟記錄操作。

如果我們想要在某一時刻停止CPU使用情況記錄操作,就需要呼叫下面這個函式:

func stopCPUProfile() {     if *cpuProfile != "" {         pprof.StopCPUProfile() // 把記錄的概要資訊寫到已指定的檔案     } }

在這個函式中,並沒有程式碼用於CPU概要檔案寫入操作。實際上,在啟動CPU使用情況記錄操作之後,執行時系統就會以每秒100次的頻率將取樣資料寫入到CPU概要檔案中。pprof.StopCPUProfile函式透過把CPU使用情況取樣的頻率設定為0來停止取樣操作。並且,只有當所有CPU使用情況記錄都被寫入到CPU概要檔案之後,pprof.StopCPUProfile函式才會退出。從而保證了CPU概要檔案的完整性。

記憶體概要檔案

記憶體概要檔案用於儲存在使用者程式執行期間的記憶體使用情況。這裡所說的記憶體使用情況,其實就是程式執行過程中堆記憶體的分配情況。Go語言執行時系統會對使用者程式執行期間的所有的堆記憶體分配進行記錄。不論在取樣的那一時刻、堆記憶體已用位元組數是否有增長,只要有位元組被分配且數量足夠,分析器就會對其進行取樣。開啟記憶體使用情況記錄的方式如下:

func startMemProfile() {     if *memProfile != "" && *memProfileRate > 0 {         runtime.MemProfileRate = *memProfileRate     } }

我們可以看到,開啟記憶體使用情況記錄的方式非常簡單。在函式startMemProfile中,只有在*memProfile和*memProfileRate的值有效時才會進行後續操作。*memProfile的含義是記憶體概要檔案的絕對路徑。*memProfileRate的含義是分析器的取樣間隔,單位是位元組。當我們將這個值賦給int型別的變數runtime.MemProfileRate時,就意味著分析器將會在每分配指定的位元組數量後對記憶體使用情況進行取樣。實際上,即使我們不給runtime.MemProfileRate變數賦值,記憶體使用情況的取樣操作也會照樣進行。此取樣操作會從使用者程式開始時啟動,且一直持續進行到使用者程式結束。runtime.MemProfileRate變數的預設值是512 * 1024,即512K個位元組。只有當我們顯式的將0賦給runtime.MemProfileRate變數之後,才會取消取樣操作。

在預設情況下,記憶體使用情況的取樣資料只會被儲存在執行時記憶體中,而儲存到檔案的操作只能由我們自己來完成。請看如下程式碼:

func stopMemProfile() {     if *memProfile != "" {         f, err := os.Create(*memProfile)         if err != nil {             fmt.Fprintf(os.Stderr, "Can not create mem profile output file: %s", err)             return         }         if err = pprof.WriteHeapProfile(f); err != nil {             fmt.Fprintf(os.Stderr, "Can not write %s: %s", *memProfile, err)         }         f.Close()     } }

從函式名稱上看,stopMemProfile函式的功能是停止對記憶體使用情況的取樣操作。但是,它只做了將取樣資料儲存到記憶體概要檔案的操作。在stopMemProfile函式中,我們呼叫了函式pprof.WriteHeapProfile,並把代表記憶體概要檔案的檔案例項作為了引數。如果pprof.WriteHeapProfile函式沒有返回錯誤,就說明資料已被寫入到了記憶體概要檔案中。

需要注意的是,對記憶體使用情況進行取樣的程式會假定取樣間隔在使用者程式的執行期間內都是一成不變的,並且等於runtime.MemProfileRate變數的當前值。因此,我們應該在我們的程式中只改變記憶體取樣間隔一次,且應儘早改變。比如,在命令原始碼檔案的main函式的開始處就改變它。

程式阻塞概要檔案

程式阻塞概要檔案用於儲存使用者程式中的Goroutine阻塞事件的記錄。我們來看開啟這項操作的方法:

func startBlockProfile() {     if *blockProfile != "" && *blockProfileRate > 0 {         runtime.SetBlockProfileRate(*blockProfileRate)     } }

與開啟記憶體使用情況記錄的方式類似,在函式startBlockProfile中,當*blockProfile和*blockProfileRate的值有效時,我們會設定對Goroutine阻塞事件的取樣間隔。*blockProfile的含義為程式阻塞概要檔案的絕對路徑。*blockProfileRate的含義是分析器的取樣間隔,單位是次。函式runtime.SetBlockProfileRate的唯一引數是int型別的。它的含義是分析器會在每發生幾次Goroutine阻塞事件時對這些事件進行取樣。如果我們不顯式的使用runtime.SetBlockProfileRate函式設定取樣間隔,那麼取樣間隔就為1。也就是說,在預設情況下,每發生一次Goroutine阻塞事件,分析器就會取樣一次。與記憶體使用情況記錄一樣,執行時系統對Goroutine阻塞事件的取樣操作也會貫穿於使用者程式的整個執行期。但是,如果我們透過runtime.SetBlockProfileRate函式將這個取樣間隔設定為0或者負數,那麼這個取樣操作就會被取消。

我們在程式結束之前可以將被儲存在執行時記憶體中的Goroutine阻塞事件記錄存放到指定的檔案中。程式碼如下:

func stopBlockProfile() {     if *blockProfile != "" && *blockProfileRate >= 0 {         f, err := os.Create(*blockProfile)         if err != nil {             fmt.Fprintf(os.Stderr, "Can not create block profile output file: %s", err)             return         }         if err = pprof.Lookup("block").WriteTo(f, 0); err != nil {             fmt.Fprintf(os.Stderr, "Can not write %s: %s", *blockProfile, err)         }         f.Close()     } }

在建立程式阻塞概要檔案之後,stopBlockProfile函式會先透過函式pprof.Lookup將儲存在執行時記憶體中的記憶體使用情況記錄取出,並在記錄的例項上呼叫WriteTo方法將記錄寫入到檔案中。

更多的概要檔案

我們可以透過pprof.Lookup函式取出更多種類的取樣記錄。如下表:

表0-20 可從pprof.Lookup函式中取出的記錄

名稱  說明  取樣頻率

goroutine 活躍Goroutine的資訊的記錄。  僅在獲取時取樣一次。

threadcreate  系統執行緒建立情況的記錄。  僅在獲取時取樣一次。

heap  堆記憶體分配情況的記錄。 預設每分配512K位元組時取樣一次。

block Goroutine阻塞事件的記錄。 預設每發生一次阻塞事件時取樣一次。

在上表中,前兩種記錄均為一次取樣的記錄,具有即時性。而後兩種記錄均為多次取樣的記錄,具有實時性。實際上,後兩種記錄“heap”和“block”正是我們前面講到的記憶體使用情況記錄和程式阻塞情況記錄。

我們知道,在使用者程式執行期間各種狀態是在不斷變化的。尤其對於後兩種記錄來說,隨著取樣次數的增多,記錄項的數量也會不斷增長。而對於前兩種記錄“goroutine”和“threadcreate”來說,如果有新的活躍Goroutine產生或新的系統執行緒被建立,其記錄項數量也會增大。所以,Go語言的執行時系統在從記憶體中獲取記錄時都會先預估一個記錄項數量。如果在從預估記錄項數量到獲取記錄之間的時間裡又有新記錄項產生,那麼執行時系統會試圖重新獲取全部記錄項。另外,執行時系統使用切片來裝載所有記錄項的。如果當前使用的切片裝不下所有記錄項,執行時系統會根據當前記錄項總數建立一個更大的切片,並再次試圖裝載所有記錄項。直到這個切片足以裝載所有的記錄項為止。但是,如果記錄項增長過快的話,執行時系統將不得不不斷的進行嘗試。這可能導致過多的時間消耗。對於前兩種記錄“goroutine”和“threadcreate”來說,執行時系統建立的切片的大小為當前記錄項總數再加10。對於前兩種記錄“heap”和“block”來說,執行時系統建立的切片的大小為當前記錄項總數再加50。雖然上述情況發生的機率可能並不會太高,但是如果我們在對某些高併發的使用者程式獲取上述記錄的時候耗費的時間過長,可以先排查一下這類原因。實際上,我們在前面介紹的這幾 種記錄操作更適合用於對高併發的使用者程式進行狀態檢測。

我們可以透過下面這個函式分別將四種記錄輸出到檔案。

func SaveProfile(workDir string, profileName string, ptype ProfileType, debug int) {     absWorkDir := getAbsFilePath(workDir)     if profileName == "" {         profileName = string(ptype)     }     profilePath := filepath.Join(absWorkDir, profileName)     f, err := os.Create(profilePath)     if err != nil {         fmt.Fprintf(os.Stderr, "Can not create profile output file: %s", err)         return     }     if err = pprof.Lookup(string(ptype)).WriteTo(f, debug); err != nil {         fmt.Fprintf(os.Stderr, "Can not write %s: %s", profilePath, err)     }     f.Close() }

函式SaveProfile有四個引數。第一個引數是概要檔案的存放目錄。第二個引數是概要檔案的名稱。第三個引數是概要檔案的型別。其中,型別ProfileType只是為string型別起的一個別名而已。這樣是為了對它的值進行限制。它的值必須為“goroutine”、“threadcreate”、“heap”或“block”中的一個。我們現在來重點說一下第四個引數。引數debug控制著概要檔案中資訊的詳細程度。這個引數也就是傳給結構體pprof.Profile的指標方法WriteTo的第二個引數。而pprof.Profile結構體的例項的指標由函式pprof.Lookup產生。下面我們看看引數debug的值與寫入概要檔案的記錄項內容的關係。

表0-21 引數debug對概要檔案內容的影響

記錄debug  小於等於0 等於1 大於等於2

goroutine 為每個記錄項提供呼叫棧中各項的以十六進位制表示的記憶體地址。  在左邊提供的資訊的基礎上,為每個記錄項的呼叫棧中各項提供與記憶體地址對應的帶程式碼包匯入路徑的函式名和原始碼檔案路徑及原始碼所在行號。 以高可讀的方式提供各活躍Goroutine的狀態資訊和呼叫棧資訊。

threadcreate  同上。 同上。 同左。

heap  同上。 在左邊提供的資訊的基礎上,為每個記錄項的呼叫棧中各項提供與記憶體地址對應的帶程式碼包匯入路徑的函式名和原始碼檔案路徑及原始碼所在行,並提供記憶體狀態資訊。  同左。

block 同上。 在左邊提供的資訊的基礎上,為每個記錄項的呼叫棧中各項提供與記憶體地址對應的帶程式碼包匯入路徑的函式名和原始碼檔案路徑及原始碼所在行號。 同左。

從上表可知,當debug的值小於等於0時,執行時系統僅會將每個記錄項中的基本資訊寫入到概要檔案中。記錄項的基本資訊只包括其呼叫棧中各項的以十六進位制表示的記憶體地址。debug的值越大,我們能從概要檔案中獲取的資訊越多。但是,go tool pprof命令會無視那些除基本資訊以外的附加資訊。實際上,執行時系統在向概要檔案中寫入附加資訊時會在最左邊加入“#”,以表示當前行為註釋行。也正因為有了這個字首,go tool pprof命令才會略過對這些附加資訊的解析。這其中有一個例外,那就是當debug大於等於2時,Goroutine記錄並不是在基本資訊的基礎上附加資訊,而是完全以高可讀的方式寫入各活躍Goroutine的狀態資訊和呼叫棧資訊。並且,在所有行的最左邊都沒有字首“#”。顯然,這個概要檔案是無法被go tool pprof命令解析的。但是它對於我們來說會更加直觀和有用。

至此,我們已經介紹了使用標準庫程式碼包runtime和runtime/pprof中的程式生成概要檔案的全部方法。在上面示例中的所有程式碼都被儲存在goc2p專案的程式碼包basic/prof中。程式碼包basic/prof中的這些程式非常易於使用。不過由於Go語言目前沒有類似停機鉤子(Shutdown Hook)的API(應用程式介面),所以程式碼包basic/prof中的程式目前只能以侵入式的方式被使用。

pprof工具

我們在上一小節中提到過,任何以go tool開頭的Go命令內部指向的特殊工具都被儲存在目錄$GOROOT/pkg/tool/$GOOS_$GOARCH/中。我們把這個目錄叫做Go工具目錄。與其他特殊工具不同的是,pprof工具並不是用Go語言編寫的,而是由Perl語言編寫的。(Perl是一種通用的、動態的解釋型程式語言)與Go語言不同,Perl語言可以直接讀取原始碼並執行。正因為如此,pprof工具的原始碼檔案被直接儲存在了Go工具目錄下。而對於其它Go工具,存在此目錄的都是經過編譯而生成的可執行檔案。我們可以直接用任意一種文字檢視工具開啟在Go工具目錄下的pprof工具的原始碼檔案pprof。實際上,這個原始碼檔案複製自Google公司發起的開源專案gperftools。此專案中包含了很多有用的工具。這些工具可以幫助開發者建立更健壯的應用程式。pprof就是其中的一個非常有用的工具。

因為pprof工具是用Perl語言編寫的,所以執行go tool pprof命令的前提條件是需要在當前環境下安裝Perl語言,推薦的版本號是5.x。關於Perl語言的安裝方法就不在這裡敘述了,讀者可以自己找到方法並自行安裝它。在安裝完Perl語言之後,我們可以在命令列終端中進入到Go工具目錄,並執行命令perl pprof。它與我們在任意目錄下執行go tool pprof命令的效果是一樣的。當然,如果想要讓go tool pprof命令在任意目錄下都可以被執行,我們需要先設定好與Go語言相關的環境變數。

我們在本小節已經討論過,go tool pprof命令會分析指定的概要檔案並使得我們能夠以互動式的方式訪問其中的資訊。但是光有概要檔案還不夠,我們還需要概要檔案中資訊的來源——命令原始碼檔案的可執行檔案。畢竟,概要檔案中的資訊是對在執行期間的使用者程式取樣的結果。而可以執行的Go語言程式只能是編譯命令原始碼檔案後生成的可執行檔案。因此,為了演示go tool pprof命令的用法,我們還建立或改造一個命令原始碼檔案。在我們的goc2p專案的程式碼包中有一個名稱為showpds.go的命令原始碼檔案。這個命令原始碼檔案用來解析指定的程式碼包的依賴關係,並將這些依賴關係列印到標準輸出裝置上。選用這個命令原始碼檔案的原因是,我們可以透過改變指定的程式碼包來控制這個命令原始碼檔案的執行時間的長短。不同的程式碼包可能會有不同數量的直接依賴包和間接依賴包。依賴包越多的程式碼包會使這個命令原始碼檔案耗費更多的時間來解析它的依賴關係。命令原始碼檔案執行的時間越長,我們得到的概要檔案中的資訊就越有意義。為了生成概要檔案,我們需要稍微的改造一下這個命令原始碼檔案。首先我們需要在這個檔案中匯入程式碼包basic/prof。然後,我們需要在它的main函式的開頭加入一行程式碼prof.Start()。這行程式碼的含義是檢查相關標記,並在標記有效時開啟或設定對應的使用情況記錄操作。最後,我們還需要在main函式的defer程式碼塊中加入一行程式碼prof.Stop()。這行程式碼的含義是,獲取已開啟的記錄的取樣資料並將它們寫入到指定的概要檔案中。透過這三個步驟,我們就已經把生成執行時概要檔案的功能附加到這個命令原始碼檔案中了。為了開啟這些功能,我還需要在透過執行go run命令來執行這個命令原始碼檔案的時候,加入相應的標記。對程式碼包basic/prof中的程式有效的標記如下表。

表0-22 對程式碼包basic/prof的API有效的標記

標記名稱  標記描述

-cpuprofile 指定CPU概要檔案的儲存路徑。該路徑可以是相對路徑也可以是絕對路徑,但其父路徑必須已存在。

-blockprofile 指定程式阻塞概要檔案的儲存路徑。該路徑可以是相對路徑也可以是絕對路徑,但其父路徑必須已存在。

-blockprofilerate 定義其值為n。此標記指定每發生n次Goroutine阻塞事件時,進行一次取樣操作。

-memprofile 指定記憶體概要檔案的儲存路徑。該路徑可以是相對路徑也可以是絕對路徑,但其父路徑必須已存在。

-memprofilerate 定義其值為n。此標記指定每分配n個位元組的堆記憶體時,進行一次取樣操作。

下面我們使用go run命令執行改造後的命令原始碼檔案showpds.go。示例如下:

hc@ubt:~/golang/goc2p$ mkdir pprof hc@ubt:~/golang/goc2p$ cd helper/pds hc@ubt:~/golang/goc2p/helper/pds$ go run showpds.go -p="runtime" cpuprofile="../../../pprof/cpu.out" -blockprofile="../../../pprof/block.out" -blockprofilerate=1 -memprofile="../../../pprof/mem.out" -memprofilerate=10 The package node of 'runtime': {/usr/local/go/src/pkg/ runtime [] [] false} The dependency structure of package 'runtime': runtime->unsafe

在上面的示例中,我們使用了所有的對程式碼包basic/prof的API有效的標記。另外,標記-p是對命令原始碼檔案showpds.go有效的。其含義是指定要解析依賴關係的程式碼包的匯入路徑。

現在我們來檢視一下goc2p專案目錄下的pprof子目錄:

hc@ubt:~/golang/goc2p/helper/pds$ ls ../../../pprof block.out  cpu.out  mem.out

這個目錄中的三個檔案分別對應了三種包含實時性資料的概要檔案。這也證明了我們對命令原始碼檔案showpds.go的改造是有效的。

好了,一切準備工作就緒。現在,我們就來看看go tool pprof命令都能做什麼。首先,我們來編譯命令原始碼檔案showpds.go。

hc@ubt:~/golang/goc2p/helper/pds$ go build showpds.go hc@ubt:~/golang/goc2p/helper/pds$ ls showpds showpds.go

然後,我們需要準備概要檔案。標準庫程式碼包runtime的依賴包極少,這使得可執行檔案showpds在極短的時間內就會執行完畢。之前我們說過,程式執行的時間越長越好。所以我們需要找到一個直接和間接依賴包都很多的程式碼包。做過Web應用系統開發的同行們都知道,一個Web應用系統的後端程式可能會有很多的依賴,不論是程式碼庫還是其他資源。根據我們的直覺,在Go語言的世界裡也應該是在這樣。在Go語言的標準庫中,程式碼包net/http專門用來為Web應用系統開發提供各種API支援。我們就用這個程式碼包來生成所需的概要檔案。

hc@ubt:~/golang/goc2p/helper/pds$ ./showpds -p="net/http" -cpuprofile="../../../pprof/cpu.out" -blockprofile="../../../pprof/block.out" -blockprofilerate=1 -memprofile="../../../pprof/mem.out" -memprofilerate=10

標準庫程式碼包net/http的依賴包很多。也正因為如此,我忽略了所有輸出的內容。讀者可以自己試試上面的這個命令。我們一口氣生成了所有能夠生成的概要檔案作為備用。這寫概要檔案被儲存在了goc2p專案的pprof目錄中。如果在上面的命令被執行前還沒有pprof目錄,命令會報錯。所以讀者需要先建立這個目錄。

現在我們就以可執行檔案showpds和pprof目錄下的CPU概要檔案cpu.out作為引數來執行go tool pprof命令。實際上,我們透過go tool pprof命令進入的就是pprof工具的互動模式的介面。

hc@ubt:~/golang/goc2p/helper/pds$ go tool pprof showpds ../../../pprof/cpu.out Welcome to pprof!  For help, type 'help'. (pprof)

我們可以在提示符“(pprof)”後面輸入一些命令來檢視概要檔案。pprof工具在互動模式下支援的命令如下表。

表0-23 pprof工具在互動模式下支援的命令

名稱  引數  標籤  說明

gv  [focus] 

將當前概要檔案以圖形化和層次化的形式顯示出來。當沒有任何引數時,在概要檔案中的所有抽樣都會被顯示。如果指定了focus引數,則只顯示呼叫棧中有名稱與此引數相匹配的函式或方法的抽樣。focus引數應該是一個正規表示式。

web [focus] 

與gv命令類似,web命令也會用圖形化的方式來顯示概要檔案。但不同的是,web命令是在一個Web瀏覽器中顯示它。如果你的Web瀏覽器已經啟動,那麼它的顯示速度會非常快。如果想改變所使用的Web瀏覽器,可以在Linux下設定符號連結/etc/alternatives/gnome-www-browser或/etc/alternatives/x-www-browser,或在OS X下改變SVG檔案的關聯Finder。

list  [routine_regexp]  

列出名稱與引數“routine_regexp”代表的正規表示式相匹配的函式或方法的相關原始碼。

weblist [routine_regexp]  

在Web瀏覽器中顯示與list命令的輸出相同的內容。它與list命令相比的優勢是,在我們點選某行原始碼時還可以顯示相應的彙編程式碼。

top[N]  

[--cum] top命令可以以本地取樣計數為順序列出函式或方法及相關資訊。如果存在標記“--cum”則以累積取樣計數為順序。預設情況下top命令會列出前10項內容。但是如果在top命令後面緊跟一個數字,那麼其列出的項數就會與這個數字相同。

disasm  [routine_regexp]  

顯示名稱與引數“routine_regexp”相匹配的函式或方法的反彙編程式碼。並且,在顯示的內容中還會標註有相應的取樣計數。

callgrind [filename]  

利用callgrind工具生成統計檔案。在這個檔案中,說明了程式中函式的呼叫情況。如果未指定“filename”引數,則直接呼叫kcachegrind工具。kcachegrind可以以視覺化的方式檢視callgrind工具生成的統計檔案。

help  

顯示幫助資訊。

quit  

退出go tool pprof命令。Ctrl-d也可以達到同樣效果。

在上面表格中的絕大多數命令(除了help和quit)都可以在其所有引數和標籤後追加一個或多個引數,以表示想要忽略顯示的函式或方法的名稱。我們需要在此類引數上加入減號“-”作為字首,並且多個引數之間需要以空格分隔。當然,我們也可以用正規表示式替代函式或方法的名稱。追加這些約束之後,任何呼叫棧中包含名稱與這類引數相匹配的函式或方法的抽樣都不會出現在命令的輸出內容中。下面我們對這幾個命令進行逐一說明。

gv命令

對於命令gv的用法,請看如下示例:

hc@ubt:~/golang/goc2p/helper/pds$ go tool pprof showpds ../../../pprof/cpu.out Welcome to pprof!  For help, type 'help'. (pprof) gv Total: 101 samples sh: 1: dot: not found go tool pprof: signal: broken pipe

其中,“(pprof)”是pprof工具在互動模式下的提示符。

從輸出資訊中我們可以看到,gv命令並沒有正確的被執行。原因是沒有找到命令dot。經查,這個命令屬於一個開源軟體Graphviz。Graphviz的核心功能是圖表的視覺化。我們可以透過命令sudo apt-get install graphviz來安裝這個軟體。注意,上面這條命令僅可用於Debian的Linux發行版及其衍生版。如果是在Redhat的Linux發行版及其衍生版下,可以使用命令“yum install graphviz”來安裝Graphviz。安裝好Graphviz後,我們再來執行gv命令。

(pprof) gv Total: 101 samples gv -scale 0 (pprof) sh: 1: gv: not found

現在,輸出資訊有提示我們沒有找到命令gv。gv是自由軟體工程專案GNU(GNU's Not Unix)中的一款開源軟體,用來以圖形化的方式檢視PDF文件。我們以同樣的方式安裝它。在Debian的Linux發行版及其衍生版下,執行命令sudo apt-get install gv,在Redhat的Linux發行版及其衍生版下,執行命令yum install gv。軟體gv被安裝好後,我們再次執行gv命令。在執行著圖形介面軟體的Linux作業系統下,會彈出這樣一個視窗。如圖5-3。

pprof工具的gv命令的執行結果

圖0-3 pprof工具的gv命令的執行結果

我們看到,在概要圖的最上面顯示了一些基本的資訊。其中,“showpds”是我們生成概要檔案時用到的那個可執行檔案。它也是概要檔案中內容的來源。“Total samples:”後面的數字23的含義是在本次程式執行期間分析器一共進行了23次取樣。我們已經知道,CPU使用情況的取樣操作會以每10毫秒一次的頻率進行。因此,取樣23次就意味著程式執行所花費的CPU時間大約為10毫秒 * 23 = 0.23秒。由於我們並沒有在gv命令後加入用於約束顯示內容的引數focus,所以在“Focusing on:”後面的數字也是23。也正是由於這個原因,後邊兩行資訊中的數字均為0。讀者可以自行試驗一下在gv命令後加入focus引數的情形,例如:gv ShowDepStruct。在下面的描述中,我們把函式和方法統稱為函式。

現在,我們把視線放在主要的圖形上。此圖形由矩形和有向線段組成。在此圖形的大多數矩形中都包含三行資訊。第一行是函式的名字。第二行包含了該函式的本地取樣計數(在括號左邊的數字)及其在取樣總數中所佔的比例(在括號內的百分比)。第三行則包含了該函式的累積取樣計數(括號左邊的數字)及其在取樣總數中所佔的比例(在括號內的百分比)。

首先,讀者需要搞清楚兩個相似但不相同的概念,即:本地取樣計數和累積取樣計數。本地取樣計數的含義是當前函式在取樣中直接出現的次數。累積取樣計數的含義是當前函式以及當前函式直接或間接呼叫的函式在取樣中直接出現的次數。所以,存在這樣一種場景:對於一個函式來說,它的本地取樣計數是0。因為它沒有在取樣中直接出現過。但是,由於它直接或間接呼叫的函式頻繁的直接出現在取樣中,所以這個函式的累積取樣計數卻會很高。我們以上圖中的函式mian.main為例。由於main.main函式在所有取樣中都沒有直接出現過,所以它的本地取樣計數為0。但又由於它是命令原始碼檔案中的入口函式,程式中其他的函式都直接或間接的被它呼叫。所以,它的累積取樣計數是所有函式中最高的,達到了22。注意,不論是本地取樣計數還是累積取樣計數都沒有把函式對自身的呼叫計算在內。函式對自身的呼叫又被稱為遞迴呼叫。

最後需要說明的是,圖形中的有向線段表示函式之間的呼叫關係。有向線段旁邊的數字為線段起始位置的函式對線段末端位置的函式的呼叫計數。這裡所說的呼叫計數其實是以函式的累積取樣計數為依託的。更具體的講,如果有一個從函式A到函式B的有向線段且旁邊的數字為10,那麼就說明在函式B的累加取樣計數中有10次計數是由函式A對函式B的直接呼叫所引起的。也由於這個原因,函式A對函式B的呼叫計數必定小於等於函式B的累積取樣計數。

至此,我們已經對概要圖中的所有元素都進行了說明,相信讀者已經能夠讀懂它了。那麼,我們怎樣透過概要圖對程式進行分析呢?

我們可以把概要圖中的這個主要圖形看成是一張函式呼叫關係圖。在一般情況下,處在非終端節點位置的函式的本地取樣計數會非常小,至少會比該函式的累積取樣計數小很多。因為它們都是透過對其它函式的呼叫來實現自身的功能的。進一步說,所有使用Go語言編寫的程式碼的功能最後都需要依託作業系統所提供的API來實現。處在終端節點位置的函式一般都存在於平臺相關的原始碼檔案中,甚至有的函式本身就是作業系統的某個API在Go語言中的對映。它們的累積取樣計數與本地取樣計數是一致的。因此,這類函式的描述資訊只有兩行,即它的名稱和它的累積取樣計數。

現在我們已經明確了在概要圖中出現的一個函式的本地取樣計數、累積取樣計數和呼叫計數的概念和含義以及它們之間的關係。這三個計數是我們分析程式效能的重要依據。

我們可以透過一個函式的累積取樣次數計算出執行它所花費的時間。一個函式的累積取樣計數越大就說明呼叫它所花費的CPU時間越多。具體來說,我們可以用CPU取樣間隔(10毫秒)乘以函式的累積取樣計數得出它所花費的實際時間。雖然這個實際時間只精確到了10毫秒的級別,但是這對於程式效能分析來說已經足夠了。即使一個函式的累積取樣計數很大,我們也不能判定這個函式本身就是有問題的。我們應該順藤摸瓜,去尋找這個函式直接或間接呼叫的函式中最耗費CPU時間的那些函式。其實,這樣的查詢很容易,因為我們已經有了概要圖。在其中的函式呼叫關係圖中,累積取樣計數越大的函式就擁有更大的節點(圖中的矩形)面積。不過這也有例外,那就是程式的入口函式。廣義來講,在整個函式呼叫關係中處在初始位置附近且與之相連的有向線段在同一方向上至多隻有一個的函式都可以被稱作入口函式。無論它們的累積取樣計數有多大,其所屬的節點的面積都是在函式呼叫關係圖中最小的。由於出現在取樣和函式呼叫關係圖中的所有函式幾乎都源自入口函式的直接或間接的呼叫,所以入口函式的累積取樣次數必定是它們中最大的。一般情況下,我們並不需要在意入口函式的計數數值,所以在函式呼叫關係圖中也就不需要使用大面積的節點來強調它們。在圖5-3中,函式runtime.main和main.main都可以被視為入口函式。另外,在函式呼叫關係圖中,有向線段的粗細也反應了對應的呼叫計數的大小。

下面,作者總結了根據函式的相關計數來對其進行分析的三個過程:

如果一個處在終端節點位置上的函式的累積取樣計數和百分比都很大,就說明它自身花費了過多的CPU時間。這時,需要檢查這個函式所實現的功能是否確實需要花費如此多的時間。如果花費的時間超出了我們的估算,則需要透過list命令找出函式體內最耗時的程式碼並進行進一步分析。如果我們發現這個函式所承擔的職責過多,那麼可以直接將這個函式拆分成多個擁有不同職責的更小的函式。

如果一個處在非終端節點位置上的函式的累積取樣計數和百分比都很大並且超出了我們的估算,那麼我們應該首先檢視其本地取樣計數的大小。如果它的本地取樣計數和百分比也很大,我們就需要透過list命令對這個函式體中的程式碼進行進一步分析。否則,我們就應該把關注點放在其下的分支節點所對應的函式上。如果當前節點下的所有直接分支節點的函式的累積取樣計數都不大,但是直接分支節點的數量卻非常多(十幾甚至幾十個),那麼大致上可以斷定當前節點的函式承擔了過多的與流程控制相關的職責,我們需要對它進行拆分甚至重新設計。如果當前節點下的分支節點中包含累積取樣計數和百分比很大的函式,那麼我們就應該根據這個分支節點的型別(終端節點或非終端節點)來對其進行過程1或過程2的分析。

單從呼叫計數的角度,我們並不能判斷一個函式是否承擔了過多的職責或者包含了過多的流程控制邏輯。但是,我們可以把呼叫計數作為定位問題的一種輔助手段。舉個例子,如果根據過程1和過程2中的分析,我們懷疑在函式B及其呼叫的函式中可能存在效能問題,並且我們還發現函式A對函式B的呼叫計數也非常大,那麼我們就應該想到函式B在取樣中的頻繁出現也許是由函式A對函式B的頻繁呼叫引起的。在這種情況下,我們就應該先檢視函式A中的程式碼,檢查其中是否包含了過多的對函式B的不合理呼叫。如果存在不合理的呼叫,我們就應該對這部分程式碼進行重新設計。除此之外,我們還可以根據呼叫計數來判定一些小問題。比如,如果一個函式與呼叫它的所有函式都處於同一個程式碼包,那麼我們就應該考慮把被呼叫的函式的訪問許可權設定為包內私有。如果對一個函式的呼叫都是來自於同一個函式,我們可以考慮在符合單一職責原則的情況下把這兩個函式合併。讀者可能已經注意到,這與過程1中的一個建議是相互對立的。實際上,這也屬於一種推遲最佳化策略。

在上述幾個分析過程中的所有建議都不是絕對的。程式最佳化是一個複雜的過程,在很多時候都需要在多個指標或多個解決方案之間進行權衡和博弈。

在這幾個分析過程的描述中,我們多次提到了list命令。現在我們就來對它進行說明。先來看一個示例:

(pprof) list ShowDepStruct Total: 23 samples ROUTINE ====================== main.ShowDepStruct in /home/hc/golang/goc2p     /src/helper/pds/showpds.go      0     20 Total samples (flat / cumulative)      .      .   44:     }      .      .   45:     fmt.Printf("The dependency structure of package '%s':n",      pkgImportPath)      .      .   46:     ShowDepStruct(pn, "")      .      .   47: }      .      .   48:  ---      .      .   49: func ShowDepStruct(pnode *pkgtool.PkgNode, prefix string) {      .      .   50:     var buf bytes.Buffer      .      .   51:     buf.WriteString(prefix)      .      .   52:     importPath := pnode.ImportPath()      .      2   53:     buf.WriteString(importPath)      .      1   54:     deps := pnode.Deps()      .      .   55:     //fmt.Printf("P_NODE: '%s', DEP_LEN: %dn", importPath,      len(deps))      .      .   56:     if len(deps) == 0 {      .      5   57:         fmt.Printf("%sn", buf.String())      .      .   58:         return      .      .   59:     }      .      .   60:     buf.WriteString(ARROWS)      .      .   61:     for _, v := range deps {      .     12   62:         ShowDepStruct(v, buf.String())      .      .   63:     }      .      .   64: } ---      .      .   65:       .      .   66: func getPkgImportPath() string {      .      .   67:     if len(pkgImportPathFlag) > 0 {      .      .   68:         return pkgImportPathFlag      .      .   69:     } (pprof)

我們在pprof工具的互動介面中輸入了命令list ShowDepStruct之後得到了很多輸出資訊。其中,ShowDepStruct為引數routine_regexp的值。輸出資訊的第一行告訴我們CPU概要檔案中的取樣一共有23個。這與我們之前講解gv命令時看到的一樣。輸出資訊的第二行顯示,與我們提供的程式正規表示式(也就是引數routine_regexp)的值匹配的函式是main.ShowDepStruct,並且這個函式所在的原始碼檔案的絕對路徑是/home/hc/golang/goc2p/src/helper/pds/showpds.go。輸出資訊中的第三行告訴我們,在main.ShowDepStruct函式體中的程式碼的本地取樣計數的總和是0,而累積取樣計數的總和是20。在第三行最右邊的括號中,flat代表本地取樣計數,而cumulative代表累積取樣計數。這是對該行最左邊的那兩個數字(也就是0和20)的含義的提示。從輸出資訊的第四行開始是對上述原始碼檔案中的程式碼的擷取,其中包含了main.ShowDepStruct函式的原始碼。list命令在這些程式碼的左邊新增了對應的行號,這讓我們查詢程式碼更加容易。另外,在程式碼行號左邊的對應位置上顯示了每行程式碼的本地取樣計數和累積取樣計數。如果計數為0,則用英文句號“.”代替。這使得我們可以非常方便的找到存在計數值的程式碼行。

一般情況下,每行程式碼對應的本地取樣計數和累積取樣計數都應該與我們用gv命令生成的函式呼叫關係圖中的計數相同。但是,如果一行程式碼中存在多個函式呼叫的話,那麼在程式碼行號左邊的計數值就會有偏差。比如,在上述示例中,第62行程式碼ShowDepStruct(v, buf.String())的累積取樣計數是12。但是從之前的函式呼叫關係圖中我們得知,函式main.ShowDepStruct的累積取樣計數是10。它們之間的偏差是2。實際上,在程式被執行的時候,第62行程式碼是由兩個操作步驟組成的。第一個步驟是執行函式呼叫buf.String()並獲得結果。第二個步驟是,呼叫函式ShowDepStruct,同時將變數v``和執行第一個步驟所獲得的結果作為引數傳入。所以,這2個取樣計數應該歸咎於第62行程式碼中的函式呼叫子句buf.String()。也就是說,第62行程式碼的累積取樣計數由兩部分組成,即函式main.ShowDepStruct的累積取樣計數和函式bytes.(*Buffer).String的累積取樣計數。同理,示例中的第57行程式碼fmt.Printf("%sn", buf.String())```的累積取樣計數也存在偏差。讀者可以試著分析一下原因。

如果讀者想驗證上面所說的產生偏差的原因的話,可以將上面示例中的第62行程式碼和第57行程式碼分別拆成兩行,然後再對命令原始碼檔案showpds.go進行編譯、執行(記得加入相關標記)並用pprof工具的list命令進行檢視。不過,驗證這個原因還有一個更簡便的方式——使用pprof工具中的disasm命令。我們在下面的示例中執行disasm命令並後跟routine_regexp引數值ShowDepStruct。

bash (pprof) disasm ShowDepStruct Total: 23 samples ROUTINE ====================== main.ShowDepStruct      0     20 samples (flat, cumulative) 87.0% of total -------------------- /home/hc/mybook/goc2p/src/helper/pds/showpds.go      .      .    49: func ShowDepStruct(pnode *pkgtool.PkgNode, prefix string) { <省略部分輸出內容>      .     10    62: ShowDepStruct(v, buf.String())      .      .     80490ce: MOVL main.&buf+3c(SP),AX      .      .     80490d2: XORL BX,BX      .      .     80490d4: CMPL BX,AX      .      .     80490d6: JNE  main.ShowDepStruct+0x25f(SB)      .      .     80490d8: LEAL go.string.*+0x12d4(SB),BX      .      .     80490de: MOVL 0(BX),CX      .      .     80490e0: MOVL 4(BX),AX      .      .     80490e3: MOVL main.v+48(SP),BX      .      .     80490e7: MOVL BX,0(SP)      .      .     80490ea: MOVL CX,4(SP)      .      .     80490ee: MOVL AX,8(SP)      .     10     80490f2: CALL main.ShowDepStruct(SB)      .      .     80490f7: MOVL main.autotmp_0046+44(SP),DX      .      .     80490fb: MOVL main.autotmp_0048+70(SP),CX      .      .    61: for _, v := range deps {      .      .     80490ff: INCL DX      .      .     8049100: MOVL main.autotmp_0047+2c(SP),BX      .      .     8049104: CMPL BX,DX      .      .     8049106: JLT  main.ShowDepStruct+0x20b(SB)      .      .    64: }      .      .     8049108: ADDL $80,SP      .      .     804910e:    RET      .      2    62: ShowDepStruct(v, buf.String())      .      .     804910f: MOVL 8(AX),DI      .      .     8049112: MOVL 4(AX),DX      .      .     8049115: MOVL c(AX),CX      .      .     8049118: CMPL CX,DX      .      .     804911a: JCC  main.ShowDepStruct+0x273(SB)      .      .     804911c: CALL runtime.panicslice(SB)      .      .     8049121:    UD2      .      .     8049123: MOVL DX,SI      .      .     8049125: SUBL CX,SI      .      .     8049127: MOVL DI,DX      .      .     8049129: SUBL CX,DX      .      .     804912b: MOVL 0(AX),BP      .      .     804912d: ADDL CX,BP      .      .     804912f: MOVL BP,main.autotmp_0073+74(SP)      .      .     8049133: MOVL main.autotmp_0073+74(SP),BX      .      .     8049137: MOVL BX,0(SP)      .      .     804913a: MOVL SI,4(SP)      .      .     804913e: MOVL DX,8(SP)      .      2     8049142: CALL runtime.slicebytetostring(SB) <省略部分輸出內容> (pprof)   (pprof)

由於篇幅原因,我們只顯示了部分輸出內容。disasm命令與list命令的輸出內容有幾分相似。實際上,disasm命令在輸出函式main.ShowDepStruct的原始碼的同時還在每一行程式碼的下面列出了與這行程式碼對應的彙編指令。並且,命令還在每一行的最左邊的對應位置上標註了該行彙編指令的本地取樣計數和累積取樣計數,同樣以英文句號“.”代表計數為0的情況。另外,在彙編指令的左邊且僅與彙編指令以一個冒號相隔的並不是像Go語言程式碼行中那樣的行號,而是彙編指令對應的記憶體地址。

在上面這個示例中,我們只關注命令原始碼檔案showpds.go中的第62行程式碼`ShowDepStruct(v, buf.String())所對應的彙編指令。請讀者著重檢視在累積取樣計數的列上有數字的行。像這樣的行一共有四個。為了方便起見,我們把這四行摘抄如下:

     .     10    62: ShowDepStruct(v, buf.String())      .     10     80490f2: CALL main.ShowDepStruct(SB)      .      2    62: ShowDepStruct(v, buf.String())      .      2     8049142: CALL runtime.slicebytetostring(SB)

其中的第一行和第三行說明了第62行程式碼的累積取樣計數的組成,而第二行和第四行說明了存在這樣的組成的原因。其中,彙編指令CALL main.ShowDepStruct(SB)的累積取樣計數為10。也就是說,呼叫main.ShowDepStruct函式期間分析器進行了10次取樣。而彙編指令runtime.slicebytetostring(SB)的累積取樣計數為2,意味著在呼叫函式runtime.slicebytetostring期間分析器進行了2次取樣。但是,runtime.slicebytetostring函式又是做什麼用的呢?實際上,runtime.slicebytetostring函式正是被函式bytes.(*Buffer).String函式呼叫的。它實現的功能是把元素型別為byte的切片轉換為字串。綜上所述,確實像我們之前說的那樣,命令原始碼檔案showpds.go中的第62行程式碼ShowDepStruct(v, buf.String())的累積取樣計數12由函式main.ShowDepStruct的累積取樣計數10和函式bytes.(*Buffer).String的累積取樣計數2組成。

至此,我們介紹了三個非常有用的命令,它們是gv命令、list命令和disasm命令。我們可以透過gv命令以影像化的方式檢視程式中各個函式的本地取樣計數、累積取樣計數以及它們之間的呼叫關係和呼叫計數,並且可以很容易的透過節點面積的大小和有向線段的粗細找到計數值較大的節點。當我們依照之前所描述的分析過程找到可疑的高耗時的函式時,便可以使用list命令來檢視函式內部各個程式碼行的本地取樣計數和累積取樣計數情況,並能夠準確的找到使用了過多的CPU時間的程式碼。同時,我們還可以使用disasm命令來檢視函式中每行程式碼所對應的彙編指令,並找到程式碼耗時的根源所在。因此,只要我們適時配合使用上述的這三條命令,就幾乎可以在任何情況下理清程式效能問題的來龍去脈。可以說,它們是Go語言為我們提供的用於解決程式效能問題的瑞士軍刀。

但是,有時候我們只是想了解哪些函式花費的CPU時間最多。在這種情況下,前面講到的那幾個命令所產生的資料就顯得不那麼直觀了。不過不要擔心,pprof工具為此提供了top命令。請看如下示例:

bash (pprof) top Total: 23 samples        5  21.7%  21.7%        5  21.7% runtime.findfunc        5  21.7%  43.5%        5  21.7% stkbucket        3  13.0%  56.5%        3  13.0% os.(*File).write        1   4.3%  60.9%        1   4.3% MHeap_AllocLocked        1   4.3%  65.2%        1   4.3% getaddrbucket        1   4.3%  69.6%        2   8.7% runtime.MHeap_Alloc        1   4.3%  73.9%        1   4.3% runtime.SizeToClass        1   4.3%  78.3%        1   4.3% runtime.aeshashbody        1   4.3%  82.6%        1   4.3% runtime.atomicload64        1   4.3%  87.0%        1   4.3% runtime.convT2E (pprof)

在預設情況下,top命令會輸出以本地取樣計數為順序的列表。我們可以把這個列表叫做本地取樣計數排名列表。列表中的每一行都有六列。我們現在從左到右看,第一列和第二列的含義分別是:函式的本地取樣計數和該本地取樣計數在總取樣計數中所佔的比例。第四列和第五列的含義分別是:函式的累積取樣計數和該累積取樣計數在總取樣計數中所佔的比例。第五列的含義是左邊幾列資料所對應的函式的名稱。讀者應該對它們已經很熟悉了。這裡需要重點說明的是第三列。第三列的含義是目前已列印出的函式的本地取樣計數之和在總取樣計數中所佔的百分比。更具體的講,第三行第三列上的百分比值就是列表前三行的三個本地取樣計數的總和13除以總取樣計數23而得出的。我們還可以透過將第二行上的百分比值43.5%與第三行第二列上的百分比值13.0%相加得到第三行第三列上的百分比值。第三列的百分比值可以使我們很直觀的瞭解到最耗時的幾個函式總共花費掉的CPU時間的比重。我們可以利用這一比重為效能最佳化任務制定更加多樣化的目標。比如,我們的效能最佳化目標是把前四個函式的總耗時比重佔比從60.9%降低到50%,等等。

從上面的示例我們可以看出,本地取樣計數較大的函式都屬於標準庫的程式碼包或者Go語言內部。所以,我們無法或者不方便對這些函式進行最佳化。我們在之前提到過,在一般情況下,使用者程式中的函式的本地取樣計數都會非常低甚至是0。所以,如果我們編寫的函式處在本地取樣計數排名列表中的前幾名的位置上話,就說明這個函式可能存在著效能問題。這時就需要我們透過list命令產生針對於這個函式的資料並仔細進行分析。舉個例子,如果我們在函式中加入了一些併發控制程式碼(不論是同步併發控制還是非同步的併發控制)使得這個函式本身的執行時間很長並在本地取樣計數排名列表中處於前幾名的位置,那麼我們就應該仔細檢視該函式中各行程式碼的取樣計數以及它們的邏輯合理性。比如,用於同步併發控制的程式碼中是否存在產生死鎖的可能性,或者用於非同步併發控制的程式碼中是否存在協調失衡或者資源分配不均的地方。與編寫合理和優秀的併發控制程式碼有關的內容在本書的第三部分。

在預設情況下,top命令輸出的列表中只包含本地取樣計數最大的前十個函式。如果我們想自定義這個列表的項數,那麼需要在top命令後面緊跟一個項數值。比如:命令top5會輸出行數為5的列表,命令top20會輸出行數為20的列表,等等。

如果我們在top命令後加入標籤--cum,那麼輸出的列表就是以累積取樣計數為順序的。示例如下:

(pprof) top20 --cum Total: 23 samples        0   0.0%   0.0%       23 100.0% gosched0        0   0.0%   0.0%       22  95.7% main.main        0   0.0%   0.0%       22  95.7% runtime.main        0   0.0%   0.0%       16  69.6% runtime.mallocgc        0   0.0%   0.0%       12  52.2% pkgtool.(*PkgNode).Grow        0   0.0%   0.0%       11  47.8% runtime.MProf_Malloc        0   0.0%   0.0%       10  43.5% main.ShowDepStruct        0   0.0%   0.0%       10  43.5% pkgtool.getImportsFromPackage        0   0.0%   0.0%        8  34.8% cnew        0   0.0%   0.0%        8  34.8% makeslice1        0   0.0%   0.0%        8  34.8% runtime.cnewarray        0   0.0%   0.0%        7  30.4% gostringsize        0   0.0%   0.0%        7  30.4% runtime.slicebytetostring        0   0.0%   0.0%        6  26.1% pkgtool.getImportsFromGoSource        0   0.0%   0.0%        6  26.1% runtime.callers        1   4.3%   4.3%        6  26.1% runtime.gentraceback        0   0.0%   4.3%        6  26.1% runtime.makeslice        5  21.7%  26.1%        5  21.7% runtime.findfunc        5  21.7%  47.8%        5  21.7% stkbucket        0   0.0%  47.8%        4  17.4% fmt.Fprintf (pprof)

我們可以把這類列表叫做累積取樣計數排名列表。在這個列表中,有命令原始碼檔案showpds.go和程式碼包pkgtool中的函式上榜。它們都存在於專案goc2p中。在實際場景中,使用者程式中的函式一般都處於函式呼叫關係圖的上游。尤其是命令原始碼檔案的入口函式main.main。所以,它們的累積取樣計數一般都比較大,即使在累積取樣計數排名列表中名列前茅也不足為奇。不過,如果一個函式的累積取樣計數和百分比都很大,就應該引起我們的注意了。這在前面講解gv命令的時候也有所提及。如果我們想在排名列表中過濾掉一些我們不關注的函式,還可以在命令的最後追加一個或多個我們想忽略的函式的名稱或相應的正規表示式。像這樣:

(pprof) top20 --cum -fmt..* -os..* Ignoring samples in call stacks that match 'fmt..*|os..*' Total: 23 samples After ignoring 'fmt..*|os..*': 15 samples of 23 (65.2%)        0   0.0%   0.0%       15  65.2% gosched0        0   0.0%   0.0%       14  60.9% main.main        0   0.0%   0.0%       14  60.9% runtime.main        0   0.0%   0.0%       12  52.2% runtime.mallocgc        0   0.0%   0.0%        8  34.8% pkgtool.(*PkgNode).Grow        0   0.0%   0.0%        7  30.4% gostringsize        0   0.0%   0.0%        7  30.4% pkgtool.getImportsFromPackage        0   0.0%   0.0%        7  30.4% runtime.MProf_Malloc        0   0.0%   0.0%        7  30.4% runtime.slicebytetostring        0   0.0%   0.0%        6  26.1% main.ShowDepStruct        0   0.0%   0.0%        6  26.1% pkgtool.getImportsFromGoSource        0   0.0%   0.0%        5  21.7% cnew        0   0.0%   0.0%        5  21.7% makeslice1        0   0.0%   0.0%        5  21.7% runtime.cnewarray        0   0.0%   0.0%        4  17.4% runtime.callers        1   4.3%   4.3%        4  17.4% runtime.gentraceback        0   0.0%   4.3%        3  13.0% MCentral_Grow        0   0.0%   4.3%        3  13.0% runtime.MCache_Alloc        0   0.0%   4.3%        3  13.0% runtime.MCentral_AllocList        3  13.0%  17.4%        3  13.0% runtime.findfunc (pprof)

在上面的示例中,我們透過命令top20獲取累積取樣計數最大的20個函式的資訊,同時過濾掉了來自程式碼包fmt和os中的函式。

我們要詳細講解的最後一個命令是callgrind。pprof工具可以將概要轉化為強大的Valgrind工具集中的元件Callgrind支援的格式。Valgrind是可執行在Linux作業系統上的用來成分析程式效能及程式中的記憶體洩露錯誤的強力工具。而作為其中元件之一的Callgrind的功能是收集程式執行時的一些資料、函式呼叫關係等資訊。由此可知,Callgrind工具的功能基本上與我們之前使用標準庫程式碼包runtime的API對程式執行情況進行取樣的操作是一致的。

我們可以透過callgrind命令將概要檔案的內容轉化為Callgrind工具可識別的格式並儲存到檔案中。示例如下:

(pprof) callgrind cpu.callgrind Writing callgrind file to 'cpu.callgrind'. (pprof)

檔案cpu.callgrind是一個普通文字檔案,所以我們可以使用任何文字檢視器來檢視其中的內容。但更方便的是,我們可以使用callgrind命令直接檢視到圖形化的資料。現在我們來嘗試一下:

(pprof) callgrind Writing callgrind file to '/tmp/pprof2641.0.callgrind'. Starting 'kcachegrind /tmp/pprof2641.0.callgrind & ' (pprof) sh: 1: kcachegrind: not found

我們沒有在callgrind命令後新增任何作為引數的統計檔案路徑。所以callgrind命令會自行使用kcachegrind工具以視覺化的方式顯示統計資料。然而,我們的系統中還沒有安裝kcachegrind工具。

在Debian的Linux發行版及其衍生版下,我們可以直接使用命令sudo apt-get install kcachegrind來安裝kcachegrind工具。或者我們可以從<a rel="nofollow" href="" "="" style="box-sizing: border-box; background-color: transparent; color: rgb(45, 133, 202); text-decoration: none;">其官方網站下載安裝包來進行安裝。

安裝好kcachegrind工具之後,我們再來執行callgrind命令:

bash (pprof) callgrind Writing callgrind file to '/tmp/pprof2641.1.callgrind'. Starting 'kcachegrind /tmp/pprof2641.1.callgrind & ' (pprof)

從命令輸出的提示資訊可以看出,實際上callgrind命令把統計檔案儲存到了Linux的臨時資料夾/tmp中。然後使用kcachegrind工具進行檢視。下圖為在pprof工具互動模式下執行callgrind命令後彈出的kcachegrind工具介面。

使用kcachegrind工具檢視概要資料

圖0-4 使用kcachegrind工具檢視概要資料

從上圖中我們可以看到,kcachegrind工具對資料的展現非常直觀。總體上來說,介面被分為了左右兩欄。在左欄中的是概要檔案中記錄的函式的資訊列表。列表一共有五列,從左到右的含義 分別是函式的累積取樣計數在總取樣計數中的百分比、函式的本地取樣計數在總取樣計數中的百分比、函式被呼叫的總次數(包括遞迴呼叫)、函式的名稱以及函式所在的原始碼檔案的名稱。而在介面的右欄,我們檢視在左欄中選中的行的詳細資訊。kcachegrind工具的功能非常強大。不過由於對它的介紹超出了本書的範圍,所以我們就此暫告一個段落。

我們剛剛提到過,不加任何引數callgrind命令的執行分為兩個步驟——生成統計檔案和使用kcachegrind工具檢視檔案內容。還記得我們在之前已經生成了一個名為統計檔案cpu.callgrind嗎?其實,我們可以使用命令kcachegrind cpu.callgrind直接對它進行檢視。執行這個命令後所彈出的kcachegrind工具介面與我們之前看到的完全一致。

到現在為止,我們又介紹了兩個可以更直觀的統計和檢視概要檔案中資料的命令。top命令讓我們可以在命令列終端中檢視這些統計資訊。而callgrind命令使我們透過kcachegrind工具檢視概要檔案的資料成為了可能。這兩個命令都讓我們可以宏觀的、從不同維度的來檢視和分析概要檔案。它們都是非常給力的統計輔助工具。

除了上面詳細講述的那些命令之外,pprof工具在互動模式下還支援少許其它的命令。這在表5-23中也有所體現。這些命令有的只是主要命令的另一種形式(比如web命令和weblist命令),而有的只是為了提供輔助功能(比如help命令和quit命令)。

在本小節中,我們只使用go tool pprof命令對CPU概要檔案進行了檢視和分析。讀者可以試著對記憶體概要檔案和程式阻塞概要檔案進行分析。

相對於普通的程式設計方式來講,併發程式設計都是複雜的。所以,我們就更需要像pprof這樣的工具為我們保駕護航。大家可以將本小節當作一篇該工具的文件,並在需要時隨時檢視。

©著作權歸作者所有:來自51CTO部落格作者吳之恆心的原創作品,如需轉載,請註明出處,否則將追究法律責任


來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/3705/viewspace-2819638/,如需轉載,請註明出處,否則將追究法律責任。

相關文章