鍍金池/ 教程/ GO/ go tool pprof
go install
go clean
go list
go test
go doc與godoc
go build
go fix與go tool fix
go tool pprof
go run
go env
go tool cgo
標(biāo)準(zhǔn)命令詳解
go get
go vet與go tool vet

go tool pprof

我們可以使用go tool pprof命令來交互式的訪問概要文件的內(nèi)容。命令將會分析指定的概要文件,并會根據(jù)我們的要求為我們提供高可讀性的輸出信息。

在Go語言中,我們可以通過標(biāo)準(zhǔn)庫的代碼包runtimeruntime/pprof中的程序來生成三種包含實時性數(shù)據(jù)的概要文件,分別是CPU概要文件、內(nèi)存概要文件和程序阻塞概要文件。下面我們先來分別介紹用于生成這三種概要文件的API的用法。

CPU概要文件

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

在默認(rèn)情況下,Go語言的運行時系統(tǒng)會以100 Hz的的頻率對CPU使用情況進(jìn)行取樣。也就是說每秒取樣100次,即每10毫秒會取樣一次。為什么使用這個頻率呢?因為100 Hz既足夠產(chǎn)生有用的數(shù)據(jù),又不至于讓系統(tǒng)產(chǎn)生停頓。并且100這個數(shù)上也很容易做換算,比如把總?cè)佑嫈?shù)換算為每秒的取樣數(shù)。實際上,這里所說的對CPU使用情況的取樣就是對當(dāng)前的Goroutine的堆棧上的程序計數(shù)器的取樣。由此,我們就可以從樣本記錄中分析出哪些代碼是計算時間最長或者說最耗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
        }
    }
}

在函數(shù)startCPUProfile中,我們首先創(chuàng)建了一個用于存放CPU使用情況記錄的文件。這個文件就是CPU概要文件,其絕對路徑由*cpuProfile的值表示。然后,我們把這個文件的實例作為參數(shù)傳入到函數(shù)`pprof.StartCPUProfile中。如果此函數(shù)沒有返回錯誤,就說明記錄操作已經(jīng)開始。需要注意的是,只有CPU概要文件的絕對路徑有效時此函數(shù)才會開啟記錄操作。

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

func stopCPUProfile() {
    if *cpuProfile != "" {
        pprof.StopCPUProfile() // 把記錄的概要信息寫到已指定的文件
    }
}

在這個函數(shù)中,并沒有代碼用于CPU概要文件寫入操作。實際上,在啟動CPU使用情況記錄操作之后,運行時系統(tǒng)就會以每秒100次的頻率將取樣數(shù)據(jù)寫入到CPU概要文件中。pprof.StopCPUProfile函數(shù)通過把CPU使用情況取樣的頻率設(shè)置為0來停止取樣操作。并且,只有當(dāng)所有CPU使用情況記錄都被寫入到CPU概要文件之后,pprof.StopCPUProfile函數(shù)才會退出。從而保證了CPU概要文件的完整性。

內(nèi)存概要文件

內(nèi)存概要文件用于保存在用戶程序執(zhí)行期間的內(nèi)存使用情況。這里所說的內(nèi)存使用情況,其實就是程序運行過程中堆內(nèi)存的分配情況。Go語言運行時系統(tǒng)會對用戶程序運行期間的所有的堆內(nèi)存分配進(jìn)行記錄。不論在取樣的那一時刻、堆內(nèi)存已用字節(jié)數(shù)是否有增長,只要有字節(jié)被分配且數(shù)量足夠,分析器就會對其進(jìn)行取樣。開啟內(nèi)存使用情況記錄的方式如下:

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

我們可以看到,開啟內(nèi)存使用情況記錄的方式非常簡單。在函數(shù)startMemProfile中,只有在*memProfile*memProfileRate的值有效時才會進(jìn)行后續(xù)操作。*memProfile的含義是內(nèi)存概要文件的絕對路徑。*memProfileRate的含義是分析器的取樣間隔,單位是字節(jié)。當(dāng)我們將這個值賦給int類型的變量runtime.MemProfileRate時,就意味著分析器將會在每分配指定的字節(jié)數(shù)量后對內(nèi)存使用情況進(jìn)行取樣。實際上,即使我們不給runtime.MemProfileRate變量賦值,內(nèi)存使用情況的取樣操作也會照樣進(jìn)行。此取樣操作會從用戶程序開始時啟動,且一直持續(xù)進(jìn)行到用戶程序結(jié)束。runtime.MemProfileRate變量的默認(rèn)值是512 * 1024,即512K個字節(jié)。只有當(dāng)我們顯式的將0賦給runtime.MemProfileRate變量之后,才會取消取樣操作。

在默認(rèn)情況下,內(nèi)存使用情況的取樣數(shù)據(jù)只會被保存在運行時內(nèi)存中,而保存到文件的操作只能由我們自己來完成。請看如下代碼:

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()
    }
}

從函數(shù)名稱上看,stopMemProfile函數(shù)的功能是停止對內(nèi)存使用情況的取樣操作。但是,它只做了將取樣數(shù)據(jù)保存到內(nèi)存概要文件的操作。在stopMemProfile函數(shù)中,我們調(diào)用了函數(shù)pprof.WriteHeapProfile,并把代表內(nèi)存概要文件的文件實例作為了參數(shù)。如果pprof.WriteHeapProfile函數(shù)沒有返回錯誤,就說明數(shù)據(jù)已被寫入到了內(nèi)存概要文件中。

需要注意的是,對內(nèi)存使用情況進(jìn)行取樣的程序會假定取樣間隔在用戶程序的運行期間內(nèi)都是一成不變的,并且等于runtime.MemProfileRate變量的當(dāng)前值。因此,我們應(yīng)該在我們的程序中只改變內(nèi)存取樣間隔一次,且應(yīng)盡早改變。比如,在命令源碼文件的main函數(shù)的開始處就改變它。

程序阻塞概要文件

程序阻塞概要文件用于保存用戶程序中的Goroutine阻塞事件的記錄。我們來看開啟這項操作的方法:

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

與開啟內(nèi)存使用情況記錄的方式類似,在函數(shù)startBlockProfile中,當(dāng)*blockProfile*blockProfileRate的值有效時,我們會設(shè)置對Goroutine阻塞事件的取樣間隔。*blockProfile的含義為程序阻塞概要文件的絕對路徑。*blockProfileRate的含義是分析器的取樣間隔,單位是次。函數(shù)runtime.SetBlockProfileRate的唯一參數(shù)是int類型的。它的含義是分析器會在每發(fā)生幾次Goroutine阻塞事件時對這些事件進(jìn)行取樣。如果我們不顯式的使用runtime.SetBlockProfileRate函數(shù)設(shè)置取樣間隔,那么取樣間隔就為1。也就是說,在默認(rèn)情況下,每發(fā)生一次Goroutine阻塞事件,分析器就會取樣一次。與內(nèi)存使用情況記錄一樣,運行時系統(tǒng)對Goroutine阻塞事件的取樣操作也會貫穿于用戶程序的整個運行期。但是,如果我們通過runtime.SetBlockProfileRate函數(shù)將這個取樣間隔設(shè)置為0或者負(fù)數(shù),那么這個取樣操作就會被取消。

我們在程序結(jié)束之前可以將被保存在運行時內(nèi)存中的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()
    }
}

在創(chuàng)建程序阻塞概要文件之后,stopBlockProfile函數(shù)會先通過函數(shù)pprof.Lookup將保存在運行時內(nèi)存中的內(nèi)存使用情況記錄取出,并在記錄的實例上調(diào)用WriteTo方法將記錄寫入到文件中。

更多的概要文件

我們可以通過pprof.Lookup函數(shù)取出更多種類的取樣記錄。如下表:

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

名稱 說明 取樣頻率
goroutine 活躍Goroutine的信息的記錄。 僅在獲取時取樣一次。
threadcreate 系統(tǒng)線程創(chuàng)建情況的記錄。 僅在獲取時取樣一次。
heap 堆內(nèi)存分配情況的記錄。 默認(rèn)每分配512K字節(jié)時取樣一次。
block Goroutine阻塞事件的記錄。 默認(rèn)每發(fā)生一次阻塞事件時取樣一次。

在上表中,前兩種記錄均為一次取樣的記錄,具有即時性。而后兩種記錄均為多次取樣的記錄,具有實時性。實際上,后兩種記錄“heap”和“block”正是我們前面講到的內(nèi)存使用情況記錄和程序阻塞情況記錄。

我們知道,在用戶程序運行期間各種狀態(tài)是在不斷變化的。尤其對于后兩種記錄來說,隨著取樣次數(shù)的增多,記錄項的數(shù)量也會不斷增長。而對于前兩種記錄“goroutine”和“threadcreate”來說,如果有新的活躍Goroutine產(chǎn)生或新的系統(tǒng)線程被創(chuàng)建,其記錄項數(shù)量也會增大。所以,Go語言的運行時系統(tǒng)在從內(nèi)存中獲取記錄時都會先預(yù)估一個記錄項數(shù)量。如果在從預(yù)估記錄項數(shù)量到獲取記錄之間的時間里又有新記錄項產(chǎn)生,那么運行時系統(tǒng)會試圖重新獲取全部記錄項。另外,運行時系統(tǒng)使用切片來裝載所有記錄項的。如果當(dāng)前使用的切片裝不下所有記錄項,運行時系統(tǒng)會根據(jù)當(dāng)前記錄項總數(shù)創(chuàng)建一個更大的切片,并再次試圖裝載所有記錄項。直到這個切片足以裝載所有的記錄項為止。但是,如果記錄項增長過快的話,運行時系統(tǒng)將不得不不斷的進(jìn)行嘗試。這可能導(dǎo)致過多的時間消耗。對于前兩種記錄“goroutine”和“threadcreate”來說,運行時系統(tǒng)創(chuàng)建的切片的大小為當(dāng)前記錄項總數(shù)再加10。對于前兩種記錄“heap”和“block”來說,運行時系統(tǒng)創(chuàng)建的切片的大小為當(dāng)前記錄項總數(shù)再加50。雖然上述情況發(fā)生的概率可能并不會太高,但是如果我們在對某些高并發(fā)的用戶程序獲取上述記錄的時候耗費的時間過長,可以先排查一下這類原因。實際上,我們在前面介紹的這幾 種記錄操作更適合用于對高并發(fā)的用戶程序進(jìn)行狀態(tài)檢測。

我們可以通過下面這個函數(shù)分別將四種記錄輸出到文件。

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()
}

函數(shù)SaveProfile有四個參數(shù)。第一個參數(shù)是概要文件的存放目錄。第二個參數(shù)是概要文件的名稱。第三個參數(shù)是概要文件的類型。其中,類型ProfileType只是為string類型起的一個別名而已。這樣是為了對它的值進(jìn)行限制。它的值必須為“goroutine”、“threadcreate”、“heap”或“block”中的一個。我們現(xiàn)在來重點說一下第四個參數(shù)。參數(shù)debug控制著概要文件中信息的詳細(xì)程度。這個參數(shù)也就是傳給結(jié)構(gòu)體pprof.Profile的指針方法WriteTo的第二個參數(shù)。而pprof.Profile結(jié)構(gòu)體的實例的指針由函數(shù)pprof.Lookup產(chǎn)生。下面我們看看參數(shù)debug的值與寫入概要文件的記錄項內(nèi)容的關(guān)系。

表0-21 參數(shù)debug對概要文件內(nèi)容的影響

記錄\debug 小于等于0 等于1 大于等于2
goroutine 為每個記錄項提供調(diào)用棧中各項的以十六進(jìn)制表示的內(nèi)存地址。 在左邊提供的信息的基礎(chǔ)上,為每個記錄項的調(diào)用棧中各項提供與內(nèi)存地址對應(yīng)的帶代碼包導(dǎo)入路徑的函數(shù)名和源碼文件路徑及源碼所在行號。 以高可讀的方式提供各活躍Goroutine的狀態(tài)信息和調(diào)用棧信息。
threadcreate 同上。 同上。 同左。
heap 同上。 在左邊提供的信息的基礎(chǔ)上,為每個記錄項的調(diào)用棧中各項提供與內(nèi)存地址對應(yīng)的帶代碼包導(dǎo)入路徑的函數(shù)名和源碼文件路徑及源碼所在行,并提供內(nèi)存狀態(tài)信息。 同左。
block 同上。 在左邊提供的信息的基礎(chǔ)上,為每個記錄項的調(diào)用棧中各項提供與內(nèi)存地址對應(yīng)的帶代碼包導(dǎo)入路徑的函數(shù)名和源碼文件路徑及源碼所在行號。 同左。

從上表可知,當(dāng)debug的值小于等于0時,運行時系統(tǒng)僅會將每個記錄項中的基本信息寫入到概要文件中。記錄項的基本信息只包括其調(diào)用棧中各項的以十六進(jìn)制表示的內(nèi)存地址。debug的值越大,我們能從概要文件中獲取的信息越多。但是,go tool pprof命令會無視那些除基本信息以外的附加信息。實際上,運行時系統(tǒng)在向概要文件中寫入附加信息時會在最左邊加入“#”,以表示當(dāng)前行為注釋行。也正因為有了這個前綴,go tool pprof命令才會略過對這些附加信息的解析。這其中有一個例外,那就是當(dāng)debug大于等于2時,Goroutine記錄并不是在基本信息的基礎(chǔ)上附加信息,而是完全以高可讀的方式寫入各活躍Goroutine的狀態(tài)信息和調(diào)用棧信息。并且,在所有行的最左邊都沒有前綴“#”。顯然,這個概要文件是無法被go tool pprof命令解析的。但是它對于我們來說會更加直觀和有用。

至此,我們已經(jīng)介紹了使用標(biāo)準(zhǔn)庫代碼包runtimeruntime/pprof中的程序生成概要文件的全部方法。在上面示例中的所有代碼都被保存在goc2p項目的代碼包basic/prof中。代碼包basic/prof中的這些程序非常易于使用。不過由于Go語言目前沒有類似停機(jī)鉤子(Shutdown Hook)的API(應(yīng)用程序接口),所以代碼包basic/prof中的程序目前只能以侵入式的方式被使用。

pprof工具

我們在上一小節(jié)中提到過,任何以go tool開頭的Go命令內(nèi)部指向的特殊工具都被保存在目錄$GOROOT/pkg/tool/$GOOS_$GOARCH/中。我們把這個目錄叫做Go工具目錄。與其他特殊工具不同的是,pprof工具并不是用Go語言編寫的,而是由Perl語言編寫的。(Perl是一種通用的、動態(tài)的解釋型編程語言)與Go語言不同,Perl語言可以直接讀取源碼并運行。正因為如此,pprof工具的源碼文件被直接保存在了Go工具目錄下。而對于其它Go工具,存在此目錄的都是經(jīng)過編譯而生成的可執(zhí)行文件。我們可以直接用任意一種文本查看工具打開在Go工具目錄下的pprof工具的源碼文件pprof。實際上,這個源碼文件拷貝自Google公司發(fā)起的開源項目gperftools。此項目中包含了很多有用的工具。這些工具可以幫助開發(fā)者創(chuàng)建更健壯的應(yīng)用程序。pprof就是其中的一個非常有用的工具。

因為pprof工具是用Perl語言編寫的,所以執(zhí)行go tool pprof命令的前提條件是需要在當(dāng)前環(huán)境下安裝Perl語言,推薦的版本號是5.x。關(guān)于Perl語言的安裝方法就不在這里敘述了,讀者可以自己找到方法并自行安裝它。在安裝完P(guān)erl語言之后,我們可以在命令行終端中進(jìn)入到Go工具目錄,并執(zhí)行命令perl pprof。它與我們在任意目錄下執(zhí)行go tool pprof命令的效果是一樣的。當(dāng)然,如果想要讓go tool pprof命令在任意目錄下都可以被執(zhí)行,我們需要先設(shè)置好與Go語言相關(guān)的環(huán)境變量。

我們在本小節(jié)已經(jīng)討論過,go tool pprof命令會分析指定的概要文件并使得我們能夠以交互式的方式訪問其中的信息。但是光有概要文件還不夠,我們還需要概要文件中信息的來源——命令源碼文件的可執(zhí)行文件。畢竟,概要文件中的信息是對在運行期間的用戶程序取樣的結(jié)果。而可以運行的Go語言程序只能是編譯命令源碼文件后生成的可執(zhí)行文件。因此,為了演示go tool pprof命令的用法,我們還創(chuàng)建或改造一個命令源碼文件。在我們的goc2p項目的代碼包中有一個名稱為showpds.go的命令源碼文件。這個命令源碼文件用來解析指定的代碼包的依賴關(guān)系,并將這些依賴關(guān)系打印到標(biāo)準(zhǔn)輸出設(shè)備上。選用這個命令源碼文件的原因是,我們可以通過改變指定的代碼包來控制這個命令源碼文件的運行時間的長短。不同的代碼包可能會有不同數(shù)量的直接依賴包和間接依賴包。依賴包越多的代碼包會使這個命令源碼文件耗費更多的時間來解析它的依賴關(guān)系。命令源碼文件運行的時間越長,我們得到的概要文件中的信息就越有意義。為了生成概要文件,我們需要稍微的改造一下這個命令源碼文件。首先我們需要在這個文件中導(dǎo)入代碼包basic/prof。然后,我們需要在它的main函數(shù)的開頭加入一行代碼prof.Start()。這行代碼的含義是檢查相關(guān)標(biāo)記,并在標(biāo)記有效時開啟或設(shè)置對應(yīng)的使用情況記錄操作。最后,我們還需要在main函數(shù)的defer代碼塊中加入一行代碼prof.Stop()。這行代碼的含義是,獲取已開啟的記錄的取樣數(shù)據(jù)并將它們寫入到指定的概要文件中。通過這三個步驟,我們就已經(jīng)把生成運行時概要文件的功能附加到這個命令源碼文件中了。為了開啟這些功能,我還需要在通過執(zhí)行go run命令來運行這個命令源碼文件的時候,加入相應(yīng)的標(biāo)記。對代碼包basic/prof中的程序有效的標(biāo)記如下表。

表0-22 對代碼包basic/prof的API有效的標(biāo)記

標(biāo)記名稱 標(biāo)記描述
-cpuprofile 指定CPU概要文件的保存路徑。該路徑可以是相對路徑也可以是絕對路徑,但其父路徑必須已存在。
-blockprofile 指定程序阻塞概要文件的保存路徑。該路徑可以是相對路徑也可以是絕對路徑,但其父路徑必須已存在。
-blockprofilerate 定義其值為n。此標(biāo)記指定每發(fā)生n次Goroutine阻塞事件時,進(jìn)行一次取樣操作。
-memprofile 指定內(nèi)存概要文件的保存路徑。該路徑可以是相對路徑也可以是絕對路徑,但其父路徑必須已存在。
-memprofilerate 定義其值為n。此標(biāo)記指定每分配n個字節(jié)的堆內(nèi)存時,進(jì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有效的標(biāo)記。另外,標(biāo)記-p是對命令源碼文件showpds.go有效的。其含義是指定要解析依賴關(guān)系的代碼包的導(dǎo)入路徑。

現(xiàn)在我們來查看一下goc2p項目目錄下的pprof子目錄:

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

這個目錄中的三個文件分別對應(yīng)了三種包含實時性數(shù)據(jù)的概要文件。這也證明了我們對命令源碼文件showpds.go的改造是有效的。

好了,一切準(zhǔn)備工作就緒?,F(xiàn)在,我們就來看看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

然后,我們需要準(zhǔn)備概要文件。標(biāo)準(zhǔn)庫代碼包runtime的依賴包極少,這使得可執(zhí)行文件showpds在極短的時間內(nèi)就會運行完畢。之前我們說過,程序運行的時間越長越好。所以我們需要找到一個直接和間接依賴包都很多的代碼包。做過Web應(yīng)用系統(tǒng)開發(fā)的同行們都知道,一個Web應(yīng)用系統(tǒng)的后端程序可能會有很多的依賴,不論是代碼庫還是其他資源。根據(jù)我們的直覺,在Go語言的世界里也應(yīng)該是在這樣。在Go語言的標(biāo)準(zhǔn)庫中,代碼包net/http專門用來為Web應(yīng)用系統(tǒng)開發(fā)提供各種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

標(biāo)準(zhǔn)庫代碼包net/http的依賴包很多。也正因為如此,我忽略了所有輸出的內(nèi)容。讀者可以自己試試上面的這個命令。我們一口氣生成了所有能夠生成的概要文件作為備用。這寫概要文件被保存在了goc2p項目的pprof目錄中。如果在上面的命令被執(zhí)行前還沒有pprof目錄,命令會報錯。所以讀者需要先創(chuàng)建這個目錄。

現(xiàn)在我們就以可執(zhí)行文件showpds和pprof目錄下的CPU概要文件cpu.out作為參數(shù)來執(zhí)行go tool pprof命令。實際上,我們通過go tool pprof命令進(jìn)入的就是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工具在交互模式下支持的命令

名稱 參數(shù) 標(biāo)簽 說明
gv [focus] 將當(dāng)前概要文件以圖形化和層次化的形式顯示出來。當(dāng)沒有任何參數(shù)時,在概要文件中的所有抽樣都會被顯示。如果指定了focus參數(shù),則只顯示調(diào)用棧中有名稱與此參數(shù)相匹配的函數(shù)或方法的抽樣。focus參數(shù)應(yīng)該是一個正則表達(dá)式。
web [focus] 與gv命令類似,web命令也會用圖形化的方式來顯示概要文件。但不同的是,web命令是在一個Web瀏覽器中顯示它。如果你的Web瀏覽器已經(jīng)啟動,那么它的顯示速度會非???。如果想改變所使用的Web瀏覽器,可以在Linux下設(shè)置符號鏈接/etc/alternatives/gnome-www-browser或/etc/alternatives/x-www-browser,或在OS X下改變SVG文件的關(guān)聯(lián)Finder。
list [routine_regexp] 列出名稱與參數(shù)“routine_regexp”代表的正則表達(dá)式相匹配的函數(shù)或方法的相關(guān)源代碼。
weblist [routine_regexp] 在Web瀏覽器中顯示與list命令的輸出相同的內(nèi)容。它與list命令相比的優(yōu)勢是,在我們點擊某行源碼時還可以顯示相應(yīng)的匯編代碼。
top[N] [--cum] top命令可以以本地取樣計數(shù)為順序列出函數(shù)或方法及相關(guān)信息。如果存在標(biāo)記“--cum”則以累積取樣計數(shù)為順序。默認(rèn)情況下top命令會列出前10項內(nèi)容。但是如果在top命令后面緊跟一個數(shù)字,那么其列出的項數(shù)就會與這個數(shù)字相同。
disasm [routine_regexp] 顯示名稱與參數(shù)“routine_regexp”相匹配的函數(shù)或方法的反匯編代碼。并且,在顯示的內(nèi)容中還會標(biāo)注有相應(yīng)的取樣計數(shù)。
callgrind [filename] 利用callgrind工具生成統(tǒng)計文件。在這個文件中,說明了程序中函數(shù)的調(diào)用情況。如果未指定“filename”參數(shù),則直接調(diào)用kcachegrind工具。kcachegrind可以以可視化的方式查看callgrind工具生成的統(tǒng)計文件。
help 顯示幫助信息。
quit 退出go tool pprof命令。Ctrl-d也可以達(dá)到同樣效果。

在上面表格中的絕大多數(shù)命令(除了help和quit)都可以在其所有參數(shù)和標(biāo)簽后追加一個或多個參數(shù),以表示想要忽略顯示的函數(shù)或方法的名稱。我們需要在此類參數(shù)上加入減號“-”作為前綴,并且多個參數(shù)之間需要以空格分隔。當(dāng)然,我們也可以用正則表達(dá)式替代函數(shù)或方法的名稱。追加這些約束之后,任何調(diào)用棧中包含名稱與這類參數(shù)相匹配的函數(shù)或方法的抽樣都不會出現(xiàn)在命令的輸出內(nèi)容中。下面我們對這幾個命令進(jìn)行逐一說明。

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命令并沒有正確的被執(zhí)行。原因是沒有找到命令dot。經(jīng)查,這個命令屬于一個開源軟件Graphviz。Graphviz的核心功能是圖表的可視化。我們可以通過命令sudo apt-get install graphviz來安裝這個軟件。注意,上面這條命令僅可用于Debian的Linux發(fā)行版及其衍生版。如果是在Redhat的Linux發(fā)行版及其衍生版下,可以使用命令“yum install graphviz”來安裝Graphviz。安裝好Graphviz后,我們再來執(zhí)行g(shù)v命令。

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

現(xiàn)在,輸出信息有提示我們沒有找到命令gv。gv是自由軟件工程項目GNU(GNU's Not Unix)中的一款開源軟件,用來以圖形化的方式查看PDF文檔。我們以同樣的方式安裝它。在Debian的Linux發(fā)行版及其衍生版下,執(zhí)行命令sudo apt-get install gv,在Redhat的Linux發(fā)行版及其衍生版下,執(zhí)行命令yum install gv。軟件gv被安裝好后,我們再次執(zhí)行g(shù)v命令。在運行著圖形界面軟件的Linux操作系統(tǒng)下,會彈出這樣一個窗口。如圖5-3。

http://wiki.jikexueyuan.com/project/go-command-tutorial/images/0-3.jpg" alt="pprof工具的gv命令的執(zhí)行結(jié)果" />

圖0-3 pprof工具的gv命令的執(zhí)行結(jié)果

我們看到,在概要圖的最上面顯示了一些基本的信息。其中,“showpds”是我們生成概要文件時用到的那個可執(zhí)行文件。它也是概要文件中內(nèi)容的來源。“Total samples:”后面的數(shù)字23的含義是在本次程序執(zhí)行期間分析器一共進(jìn)行了23次取樣。我們已經(jīng)知道,CPU使用情況的取樣操作會以每10毫秒一次的頻率進(jìn)行。因此,取樣23次就意味著程序運行所花費的CPU時間大約為10毫秒 * 23 = 0.23秒。由于我們并沒有在gv命令后加入用于約束顯示內(nèi)容的參數(shù)focus,所以在“Focusing on:”后面的數(shù)字也是23。也正是由于這個原因,后邊兩行信息中的數(shù)字均為0。讀者可以自行試驗一下在gv命令后加入focus參數(shù)的情形,例如:gv ShowDepStruct。在下面的描述中,我們把函數(shù)和方法統(tǒng)稱為函數(shù)。

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

首先,讀者需要搞清楚兩個相似但不相同的概念,即:本地取樣計數(shù)和累積取樣計數(shù)。本地取樣計數(shù)的含義是當(dāng)前函數(shù)在取樣中直接出現(xiàn)的次數(shù)。累積取樣計數(shù)的含義是當(dāng)前函數(shù)以及當(dāng)前函數(shù)直接或間接調(diào)用的函數(shù)在取樣中直接出現(xiàn)的次數(shù)。所以,存在這樣一種場景:對于一個函數(shù)來說,它的本地取樣計數(shù)是0。因為它沒有在取樣中直接出現(xiàn)過。但是,由于它直接或間接調(diào)用的函數(shù)頻繁的直接出現(xiàn)在取樣中,所以這個函數(shù)的累積取樣計數(shù)卻會很高。我們以上圖中的函數(shù)mian.main為例。由于main.main函數(shù)在所有取樣中都沒有直接出現(xiàn)過,所以它的本地取樣計數(shù)為0。但又由于它是命令源碼文件中的入口函數(shù),程序中其他的函數(shù)都直接或間接的被它調(diào)用。所以,它的累積取樣計數(shù)是所有函數(shù)中最高的,達(dá)到了22。注意,不論是本地取樣計數(shù)還是累積取樣計數(shù)都沒有把函數(shù)對自身的調(diào)用計算在內(nèi)。函數(shù)對自身的調(diào)用又被稱為遞歸調(diào)用。

最后需要說明的是,圖形中的有向線段表示函數(shù)之間的調(diào)用關(guān)系。有向線段旁邊的數(shù)字為線段起始位置的函數(shù)對線段末端位置的函數(shù)的調(diào)用計數(shù)。這里所說的調(diào)用計數(shù)其實是以函數(shù)的累積取樣計數(shù)為依托的。更具體的講,如果有一個從函數(shù)A到函數(shù)B的有向線段且旁邊的數(shù)字為10,那么就說明在函數(shù)B的累加取樣計數(shù)中有10次計數(shù)是由函數(shù)A對函數(shù)B的直接調(diào)用所引起的。也由于這個原因,函數(shù)A對函數(shù)B的調(diào)用計數(shù)必定小于等于函數(shù)B的累積取樣計數(shù)。

至此,我們已經(jīng)對概要圖中的所有元素都進(jìn)行了說明,相信讀者已經(jīng)能夠讀懂它了。那么,我們怎樣通過概要圖對程序進(jìn)行分析呢?

我們可以把概要圖中的這個主要圖形看成是一張函數(shù)調(diào)用關(guān)系圖。在一般情況下,處在非終端節(jié)點位置的函數(shù)的本地取樣計數(shù)會非常小,至少會比該函數(shù)的累積取樣計數(shù)小很多。因為它們都是通過對其它函數(shù)的調(diào)用來實現(xiàn)自身的功能的。進(jìn)一步說,所有使用Go語言編寫的代碼的功能最后都需要依托操作系統(tǒng)所提供的API來實現(xiàn)。處在終端節(jié)點位置的函數(shù)一般都存在于平臺相關(guān)的源碼文件中,甚至有的函數(shù)本身就是操作系統(tǒng)的某個API在Go語言中的映射。它們的累積取樣計數(shù)與本地取樣計數(shù)是一致的。因此,這類函數(shù)的描述信息只有兩行,即它的名稱和它的累積取樣計數(shù)。

現(xiàn)在我們已經(jīng)明確了在概要圖中出現(xiàn)的一個函數(shù)的本地取樣計數(shù)、累積取樣計數(shù)和調(diào)用計數(shù)的概念和含義以及它們之間的關(guān)系。這三個計數(shù)是我們分析程序性能的重要依據(jù)。

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

下面,作者總結(jié)了根據(jù)函數(shù)的相關(guān)計數(shù)來對其進(jìn)行分析的三個過程:

  1. 如果一個處在終端節(jié)點位置上的函數(shù)的累積取樣計數(shù)和百分比都很大,就說明它自身花費了過多的CPU時間。這時,需要檢查這個函數(shù)所實現(xiàn)的功能是否確實需要花費如此多的時間。如果花費的時間超出了我們的估算,則需要通過list命令找出函數(shù)體內(nèi)最耗時的代碼并進(jìn)行進(jìn)一步分析。如果我們發(fā)現(xiàn)這個函數(shù)所承擔(dān)的職責(zé)過多,那么可以直接將這個函數(shù)拆分成多個擁有不同職責(zé)的更小的函數(shù)。

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

  3. 單從調(diào)用計數(shù)的角度,我們并不能判斷一個函數(shù)是否承擔(dān)了過多的職責(zé)或者包含了過多的流程控制邏輯。但是,我們可以把調(diào)用計數(shù)作為定位問題的一種輔助手段。舉個例子,如果根據(jù)過程1和過程2中的分析,我們懷疑在函數(shù)B及其調(diào)用的函數(shù)中可能存在性能問題,并且我們還發(fā)現(xiàn)函數(shù)A對函數(shù)B的調(diào)用計數(shù)也非常大,那么我們就應(yīng)該想到函數(shù)B在取樣中的頻繁出現(xiàn)也許是由函數(shù)A對函數(shù)B的頻繁調(diào)用引起的。在這種情況下,我們就應(yīng)該先查看函數(shù)A中的代碼,檢查其中是否包含了過多的對函數(shù)B的不合理調(diào)用。如果存在不合理的調(diào)用,我們就應(yīng)該對這部分代碼進(jìn)行重新設(shè)計。除此之外,我們還可以根據(jù)調(diào)用計數(shù)來判定一些小問題。比如,如果一個函數(shù)與調(diào)用它的所有函數(shù)都處于同一個代碼包,那么我們就應(yīng)該考慮把被調(diào)用的函數(shù)的訪問權(quán)限設(shè)置為包內(nèi)私有。如果對一個函數(shù)的調(diào)用都是來自于同一個函數(shù),我們可以考慮在符合單一職責(zé)原則的情況下把這兩個函數(shù)合并。讀者可能已經(jīng)注意到,這與過程1中的一個建議是相互對立的。實際上,這也屬于一種推遲優(yōu)化策略。

在上述幾個分析過程中的所有建議都不是絕對的。程序優(yōu)化是一個復(fù)雜的過程,在很多時候都需要在多個指標(biāo)或多個解決方案之間進(jìn)行權(quán)衡和博弈。

在這幾個分析過程的描述中,我們多次提到了list命令?,F(xiàn)在我們就來對它進(jìn)行說明。先來看一個示例:

(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: %d\n", importPath,
     len(deps))
     .      .   56:     if len(deps) == 0 {
     .      5   57:         fmt.Printf("%s\n", 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為參數(shù)routine_regexp的值。輸出信息的第一行告訴我們CPU概要文件中的取樣一共有23個。這與我們之前講解gv命令時看到的一樣。輸出信息的第二行顯示,與我們提供的程序正則表達(dá)式(也就是參數(shù)routine_regexp)的值匹配的函數(shù)是main.ShowDepStruct,并且這個函數(shù)所在的源碼文件的絕對路徑是/home/hc/golang/goc2p/src/helper/pds/showpds.go。輸出信息中的第三行告訴我們,在main.ShowDepStruct函數(shù)體中的代碼的本地取樣計數(shù)的總和是0,而累積取樣計數(shù)的總和是20。在第三行最右邊的括號中,flat代表本地取樣計數(shù),而cumulative代表累積取樣計數(shù)。這是對該行最左邊的那兩個數(shù)字(也就是0和20)的含義的提示。從輸出信息的第四行開始是對上述源碼文件中的代碼的截取,其中包含了main.ShowDepStruct函數(shù)的源碼。list命令在這些代碼的左邊添加了對應(yīng)的行號,這讓我們查找代碼更加容易。另外,在代碼行號左邊的對應(yīng)位置上顯示了每行代碼的本地取樣計數(shù)和累積取樣計數(shù)。如果計數(shù)為0,則用英文句號“.”代替。這使得我們可以非常方便的找到存在計數(shù)值的代碼行。

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

如果讀者想驗證上面所說的產(chǎn)生偏差的原因的話,可以將上面示例中的第62行代碼和第57行代碼分別拆成兩行,然后再對命令源碼文件showpds.go進(jìn)行編譯、運行(記得加入相關(guān)標(biāo)記)并用pprof工具的list命令進(jìn)行查看。不過,驗證這個原因還有一個更簡便的方式——使用pprof工具中的disasm命令。我們在下面的示例中執(zhí)行disasm命令并后跟routine_regexp參數(shù)值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) {
<省略部分輸出內(nèi)容>
     .     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)
<省略部分輸出內(nèi)容>
(pprof) 

(pprof) 

由于篇幅原因,我們只顯示了部分輸出內(nèi)容。disasm命令與list命令的輸出內(nèi)容有幾分相似。實際上,disasm命令在輸出函數(shù)main.ShowDepStruct的源碼的同時還在每一行代碼的下面列出了與這行代碼對應(yīng)的匯編指令。并且,命令還在每一行的最左邊的對應(yīng)位置上標(biāo)注了該行匯編指令的本地取樣計數(shù)和累積取樣計數(shù),同樣以英文句號“.”代表計數(shù)為0的情況。另外,在匯編指令的左邊且僅與匯編指令以一個冒號相隔的并不是像Go語言代碼行中那樣的行號,而是匯編指令對應(yīng)的內(nèi)存地址。

在上面這個示例中,我們只關(guān)注命令源碼文件showpds.go中的第62行代碼`ShowDepStruct(v, buf.String())所對應(yīng)的匯編指令。請讀者著重查看在累積取樣計數(shù)的列上有數(shù)字的行。像這樣的行一共有四個。為了方便起見,我們把這四行摘抄如下:

     .     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行代碼的累積取樣計數(shù)的組成,而第二行和第四行說明了存在這樣的組成的原因。其中,匯編指令CALL main.ShowDepStruct(SB)的累積取樣計數(shù)為10。也就是說,調(diào)用main.ShowDepStruct函數(shù)期間分析器進(jìn)行了10次取樣。而匯編指令runtime.slicebytetostring(SB)的累積取樣計數(shù)為2,意味著在調(diào)用函數(shù)runtime.slicebytetostring期間分析器進(jìn)行了2次取樣。但是,runtime.slicebytetostring函數(shù)又是做什么用的呢?實際上,runtime.slicebytetostring函數(shù)正是被函數(shù)bytes.(*Buffer).String函數(shù)調(diào)用的。它實現(xiàn)的功能是把元素類型為byte的切片轉(zhuǎn)換為字符串。綜上所述,確實像我們之前說的那樣,命令源碼文件showpds.go中的第62行代碼ShowDepStruct(v, buf.String())的累積取樣計數(shù)12由函數(shù)main.ShowDepStruct的累積取樣計數(shù)10和函數(shù)bytes.(*Buffer).String的累積取樣計數(shù)2組成。

至此,我們介紹了三個非常有用的命令,它們是gv命令、list命令和disasm命令。我們可以通過gv命令以圖像化的方式查看程序中各個函數(shù)的本地取樣計數(shù)、累積取樣計數(shù)以及它們之間的調(diào)用關(guān)系和調(diào)用計數(shù),并且可以很容易的通過節(jié)點面積的大小和有向線段的粗細(xì)找到計數(shù)值較大的節(jié)點。當(dāng)我們依照之前所描述的分析過程找到可疑的高耗時的函數(shù)時,便可以使用list命令來查看函數(shù)內(nèi)部各個代碼行的本地取樣計數(shù)和累積取樣計數(shù)情況,并能夠準(zhǔn)確的找到使用了過多的CPU時間的代碼。同時,我們還可以使用disasm命令來查看函數(shù)中每行代碼所對應(yīng)的匯編指令,并找到代碼耗時的根源所在。因此,只要我們適時配合使用上述的這三條命令,就幾乎可以在任何情況下理清程序性能問題的來龍去脈??梢哉f,它們是Go語言為我們提供的用于解決程序性能問題的瑞士軍刀。

但是,有時候我們只是想了解哪些函數(shù)花費的CPU時間最多。在這種情況下,前面講到的那幾個命令所產(chǎn)生的數(shù)據(jù)就顯得不那么直觀了。不過不要擔(dān)心,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) 

在默認(rèn)情況下,top命令會輸出以本地取樣計數(shù)為順序的列表。我們可以把這個列表叫做本地取樣計數(shù)排名列表。列表中的每一行都有六列。我們現(xiàn)在從左到右看,第一列和第二列的含義分別是:函數(shù)的本地取樣計數(shù)和該本地取樣計數(shù)在總?cè)佑嫈?shù)中所占的比例。第四列和第五列的含義分別是:函數(shù)的累積取樣計數(shù)和該累積取樣計數(shù)在總?cè)佑嫈?shù)中所占的比例。第五列的含義是左邊幾列數(shù)據(jù)所對應(yīng)的函數(shù)的名稱。讀者應(yīng)該對它們已經(jīng)很熟悉了。這里需要重點說明的是第三列。第三列的含義是目前已打印出的函數(shù)的本地取樣計數(shù)之和在總?cè)佑嫈?shù)中所占的百分比。更具體的講,第三行第三列上的百分比值就是列表前三行的三個本地取樣計數(shù)的總和13除以總?cè)佑嫈?shù)23而得出的。我們還可以通過將第二行上的百分比值43.5%與第三行第二列上的百分比值13.0%相加得到第三行第三列上的百分比值。第三列的百分比值可以使我們很直觀的了解到最耗時的幾個函數(shù)總共花費掉的CPU時間的比重。我們可以利用這一比重為性能優(yōu)化任務(wù)制定更加多樣化的目標(biāo)。比如,我們的性能優(yōu)化目標(biāo)是把前四個函數(shù)的總耗時比重占比從60.9%降低到50%,等等。

從上面的示例我們可以看出,本地取樣計數(shù)較大的函數(shù)都屬于標(biāo)準(zhǔn)庫的代碼包或者Go語言內(nèi)部。所以,我們無法或者不方便對這些函數(shù)進(jìn)行優(yōu)化。我們在之前提到過,在一般情況下,用戶程序中的函數(shù)的本地取樣計數(shù)都會非常低甚至是0。所以,如果我們編寫的函數(shù)處在本地取樣計數(shù)排名列表中的前幾名的位置上話,就說明這個函數(shù)可能存在著性能問題。這時就需要我們通過list命令產(chǎn)生針對于這個函數(shù)的數(shù)據(jù)并仔細(xì)進(jìn)行分析。舉個例子,如果我們在函數(shù)中加入了一些并發(fā)控制代碼(不論是同步并發(fā)控制還是異步的并發(fā)控制)使得這個函數(shù)本身的執(zhí)行時間很長并在本地取樣計數(shù)排名列表中處于前幾名的位置,那么我們就應(yīng)該仔細(xì)查看該函數(shù)中各行代碼的取樣計數(shù)以及它們的邏輯合理性。比如,用于同步并發(fā)控制的代碼中是否存在產(chǎn)生死鎖的可能性,或者用于異步并發(fā)控制的代碼中是否存在協(xié)調(diào)失衡或者資源分配不均的地方。與編寫合理和優(yōu)秀的并發(fā)控制代碼有關(guān)的內(nèi)容在本書的第三部分。

在默認(rèn)情況下,top命令輸出的列表中只包含本地取樣計數(shù)最大的前十個函數(shù)。如果我們想自定義這個列表的項數(shù),那么需要在top命令后面緊跟一個項數(shù)值。比如:命令top5會輸出行數(shù)為5的列表,命令top20會輸出行數(shù)為20的列表,等等。

如果我們在top命令后加入標(biāo)簽--cum,那么輸出的列表就是以累積取樣計數(shù)為順序的。示例如下:

(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) 

我們可以把這類列表叫做累積取樣計數(shù)排名列表。在這個列表中,有命令源碼文件showpds.go和代碼包pkgtool中的函數(shù)上榜。它們都存在于項目goc2p中。在實際場景中,用戶程序中的函數(shù)一般都處于函數(shù)調(diào)用關(guān)系圖的上游。尤其是命令源碼文件的入口函數(shù)main.main。所以,它們的累積取樣計數(shù)一般都比較大,即使在累積取樣計數(shù)排名列表中名列前茅也不足為奇。不過,如果一個函數(shù)的累積取樣計數(shù)和百分比都很大,就應(yīng)該引起我們的注意了。這在前面講解gv命令的時候也有所提及。如果我們想在排名列表中過濾掉一些我們不關(guān)注的函數(shù),還可以在命令的最后追加一個或多個我們想忽略的函數(shù)的名稱或相應(yīng)的正則表達(dá)式。像這樣:

(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) 

在上面

上一篇:go run下一篇:go build