天天看點

go tool pprof

我們可以使用<code>go tool pprof</code>指令來互動式的通路概要檔案的内容。指令将會分析指定的概要檔案,并會根據我們的要求為我們提供高可讀性的輸出資訊。

在Go語言中,我們可以通過标準庫的代碼包<code>runtime</code>和<code>runtime/pprof</code>中的程式來生成三種包含實時性資料的概要檔案,分别是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使用情況的記錄。

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

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

在這個函數中,并沒有代碼用于CPU概要檔案寫入操作。實際上,在啟動CPU使用情況記錄操作之後,運作時系統就會以每秒100次的頻率将取樣資料寫入到CPU概要檔案中。<code>pprof.StopCPUProfile</code>函數通過把CPU使用情況取樣的頻率設定為0來停止取樣操作。并且,隻有當所有CPU使用情況記錄都被寫入到CPU概要檔案之後,<code>pprof.StopCPUProfile</code>函數才會退出。進而保證了CPU概要檔案的完整性。

記憶體概要檔案

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

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

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

從函數名稱上看,<code>stopMemProfile</code>函數的功能是停止對記憶體使用情況的取樣操作。但是,它隻做了将取樣資料儲存到記憶體概要檔案的操作。在<code>stopMemProfile</code>函數中,我們調用了函數<code>pprof.WriteHeapProfile</code>,并把代表記憶體概要檔案的檔案執行個體作為了參數。如果<code>pprof.WriteHeapProfile</code>函數沒有傳回錯誤,就說明資料已被寫入到了記憶體概要檔案中。

需要注意的是,對記憶體使用情況進行取樣的程式會假定取樣間隔在使用者程式的運作期間内都是一成不變的,并且等于<code>runtime.MemProfileRate</code>變量的目前值。是以,我們應該在我們的程式中隻改變記憶體取樣間隔一次,且應盡早改變。比如,在指令源碼檔案的main函數的開始處就改變它。

程式阻塞概要檔案

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

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

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

在建立程式阻塞概要檔案之後,<code>stopBlockProfile</code>函數會先通過函數<code>pprof.Lookup</code>将儲存在運作時記憶體中的記憶體使用情況記錄取出,并在記錄的執行個體上調用<code>WriteTo</code>方法将記錄寫入到檔案中。

更多的概要檔案

我們可以通過<code>pprof.Lookup</code>函數取出更多種類的取樣記錄。如下表:

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

名稱

說明

取樣頻率

goroutine

活躍Goroutine的資訊的記錄。

僅在擷取時取樣一次。

threadcreate

系統線程建立情況的記錄。

heap

堆記憶體配置設定情況的記錄。

預設每配置設定512K位元組時取樣一次。

block

Goroutine阻塞事件的記錄。

預設每發生一次阻塞事件時取樣一次。

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

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

我們可以通過下面這個函數分别将四種記錄輸出到檔案。

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

表0-21 參數debug對概要檔案内容的影響

記錄\debug

小于等于0

等于1

大于等于2

為每個記錄項提供調用棧中各項的以十六進制表示的記憶體位址。

在左邊提供的資訊的基礎上,為每個記錄項的調用棧中各項提供與記憶體位址對應的帶代碼包導入路徑的函數名和源碼檔案路徑及源碼所在行号。

以高可讀的方式提供各活躍Goroutine的狀态資訊和調用棧資訊。

同上。

同左。

在左邊提供的資訊的基礎上,為每個記錄項的調用棧中各項提供與記憶體位址對應的帶代碼包導入路徑的函數名和源碼檔案路徑及源碼所在行,并提供記憶體狀态資訊。

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

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

pprof工具

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

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

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

表0-22 對代碼包basic/prof的API有效的标記

标記名稱

标記描述

-cpuprofile

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

-blockprofile

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

-blockprofilerate

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

-memprofile

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

-memprofilerate

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

下面我們使用<code>go run</code>指令運作改造後的指令源碼檔案showpds.go。示例如下:

在上面的示例中,我們使用了所有的對代碼包<code>basic/prof</code>的API有效的标記。另外,标記<code>-p</code>是對指令源碼檔案showpds.go有效的。其含義是指定要解析依賴關系的代碼包的導入路徑。

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

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

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

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

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

現在我們就以可執行檔案showpds和pprof目錄下的CPU概要檔案cpu.out作為參數來執行<code>go tool pprof</code>指令。實際上,我們通過<code>go tool pprof</code>指令進入的就是pprof工具的互動模式的界面。

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

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

參數

标簽

gv

[focus]

将目前概要檔案以圖形化和階層化的形式顯示出來。當沒有任何參數時,在概要檔案中的所有抽樣都會被顯示。如果指定了focus參數,則隻顯示調用棧中有名稱與此參數相比對的函數或方法的抽樣。focus參數應該是一個正規表達式。

web

與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

在Web浏覽器中顯示與list指令的輸出相同的内容。它與list指令相比的優勢是,在我們點選某行源碼時還可以顯示相應的彙編代碼。

top[N]

[--cum]

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

disasm

顯示名稱與參數“routine_regexp”相比對的函數或方法的反彙編代碼。并且,在顯示的内容中還會标注有相應的取樣計數。

callgrind

[filename]

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

help

顯示幫助資訊。

quit

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

在上面表格中的絕大多數指令(除了help和quit)都可以在其所有參數和标簽後追加一個或多個參數,以表示想要忽略顯示的函數或方法的名稱。我們需要在此類參數上加入減号“-”作為字首,并且多個參數之間需要以空格分隔。當然,我們也可以用正規表達式替代函數或方法的名稱。追加這些限制之後,任何調用棧中包含名稱與這類參數相比對的函數或方法的抽樣都不會出現在指令的輸出内容中。下面我們對這幾個指令進行逐一說明。

gv指令

對于指令gv的用法,請看如下示例:

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

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

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

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

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

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

首先,讀者需要搞清楚兩個相似但不相同的概念,即:本地取樣計數和累積取樣計數。本地取樣計數的含義是目前函數在取樣中直接出現的次數。累積取樣計數的含義是目前函數以及目前函數直接或間接調用的函數在取樣中直接出現的次數。是以,存在這樣一種場景:對于一個函數來說,它的本地取樣計數是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中,函數<code>runtime.main</code>和<code>main.main</code>都可以被視為入口函數。另外,在函數調用關系圖中,有向線段的粗細也反應了對應的調用計數的大小。

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

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

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

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

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

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

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

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

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

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

在上面這個示例中,我們隻關注指令源碼檔案showpds.go中的第62行代碼<code>`ShowDepStruct(v, buf.String())</code>所對應的彙編指令。請讀者着重檢視在累積取樣計數的列上有數字的行。像這樣的行一共有四個。為了友善起見,我們把這四行摘抄如下:

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

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

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

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

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

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

如果我們在top指令後加入标簽<code>--cum</code>,那麼輸出的清單就是以累積取樣計數為順序的。示例如下:

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

在上面的示例中,我們通過指令top20擷取累積取樣計數最大的20個函數的資訊,同時過濾掉了來自代碼包<code>fmt</code>和<code>os</code>中的函數。

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

我們可以通過callgrind指令将概要檔案的内容轉化為Callgrind工具可識别的格式并儲存到檔案中。示例如下:

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

我們沒有在callgrind指令後添加任何作為參數的統計檔案路徑。是以callgrind指令會自行使用kcachegrind工具以可視化的方式顯示統計資料。然而,我們的系統中還沒有安裝kcachegrind工具。

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

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

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

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

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

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

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

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

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

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

繼續閱讀