1. 程式人生 > >Go 程式的效能除錯問題

Go 程式的效能除錯問題

英文原文:Debugging performance issues in Go programs

假設你手上有個Go語言編寫的程式,你打算提升它的效能。目前有一些工具可以為此提供幫助。這些工具能幫你發現包括CPU、IO和記憶體在內多種型別的熱點。所謂熱點,是指那些為了能顯著提升效能而值得你去關注的地方。有時候這些工具還能幫助你發現程式中主要的效能瑕疵。舉個例子,你沒必要每次執行SQL查詢前都對SQL語句進行引數化解析,你可以將這個準備過程在程式啟動時一次完成。再舉個例子,當前某個演算法的複雜度是O(N²),但其實存在一個複雜度是O(N)的解決方案。為了能發現這些問題,需要理智地檢查你在優化分析器中獲取到的資訊。比如上面提到的第一個問題,你會注意到相當長的時間被花費在了對SQL語句的準備上。

 

瞭解針對性能的不同邊界因素也是比較重要的。比方說,如果一個程式使用100 Mbps頻寬的網路進行通訊,而目前已經佔用了超過90 Mbps的頻寬,為了提升它的效能,你拿這樣的程式也沒啥辦法了。在磁碟IO、記憶體消耗和計算密集型任務方面,也有類似的邊界因素。

將這點牢記在心,讓我們看看有哪些工具可以用。

注意:這些工具會彼此互相影響。例如,對記憶體使用優化分析器會導致針對CPU的優化分析器產生誤差,對goroutine阻塞使用優化分析器會影響排程器跟蹤等等。為了獲得更加精確的資訊,請在隔離的環境中使用這些工具。

注意:本文描述的用法基於Go語言釋出的1.3版。

CPU 分析器

Go 執行時包含了內建的CPU分析器,它用來展示某個函式耗費了多少CPU百分時間。這裡有三種方式來使用它:

1. 最簡單的是用"go test"的-cpuprofile選項。例如下面的命令:

$ go test -run=none -bench=ClientServerParallel4 -cpuprofile=cprof net/http

將會分析所給的基準並將結果寫入"cprof"檔案中。

然後:

$ go tool pprof --text http.test cprof

將會列印耗費最多CPU時間的函式列表。

這裡有幾種可用的輸出形式,最實用的有 --text, --web 和 --list。執行 "go tool pprof" 來得到完整的列表。

這個選項最明顯的缺點是它只能用來做測試。

2. net/http/pprof 包。這是網路伺服器的理想解決方案。你可能僅僅需要匯入net/http/pprof,然後使用下面的方法收集分析結果:

$ go tool pprof --text mybin http://myserver:6060:/debug/pprof/profile

3. 手動收集. 你需要匯入 runtime/pprof 然後再main函式中新增下面的程式碼:

   if *flagCpuprofile != "" {
       f, err := os.Create(*flagCpuprofile)
       if err != nil {
           log.Fatal(err)
       }
       pprof.StartCPUProfile(f)
       defer pprof.StopCPUProfile()
   }

分析結果會被寫入指定的檔案中,像第一種方式一樣使之視覺化。

這裡有一個使用 --web 選項來實現視覺化的例子:

cpu profile

你可以使用--list=funcname來審查單一函式。例如,下面的結果顯示了附加函式中的時間流逝:

    .      .   93: func (bp *buffer) WriteRune(r rune) error {
    .      .   94:     if r < utf8.RuneSelf {
    5      5   95:         *bp = append(*bp, byte(r))
    .      .   96:         return nil
    .      .   97:     }
    .      .   98: 
    .      .   99:     b := *bp
    .      .  100:     n := len(b)
    .      .  101:     for n+utf8.UTFMax > cap(b) {
    .      .  102:         b = append(b, 0)
    .      .  103:     }
    .      .  104:     w := utf8.EncodeRune(b[n:n+utf8.UTFMax], r)
    .      .  105:     *bp = b[:n+w]
    .      .  106:     return nil
    .      .  107: 

  

你可以在這裡找到pprof工具的詳細資訊以及上圖中數字的描述。

在3種特殊的情形下分析器不能解開堆疊:GC,System和ExternalCode。GC 表示垃圾回收期間的用時,檢視下面的記憶體分析器和垃圾回收跟蹤器以得到優化建議。System 表示goroutine排程程式,棧管理程式碼和其他輔助執行時程式碼的用時。ExternalCode 表示本地動態庫耗時。

 

對於你在簡介中看到的東西的解釋,這裡有一些提示和技巧。

如果你看到大量的時間消耗在執行時間,記憶體分配的函式,那麼暗示程式產生了大量過度的小記憶體分配工作。此描述將會告訴你這些分配來自哪裡。檢視記憶體分析器部分可以獲得如何優化這種情況的建議。可考慮對程式進行重新調整以消除頻繁對共享資源的獲取和接入。對此,一般的解決技術方案包括有分片/分割槽,本地快取/計量和寫時拷貝。

如果大量的時間消耗在頻道操作,同步。互斥程式碼和其他同步原語或者系統容器,那麼程式很可能正在飽受資源爭奪的痛苦。

如果大量的時間消耗在系統呼叫的讀/寫,那麼暗示程式產生了大量過度的小塊讀寫。對這種情況,圍繞系統檔案或者網路連線而包裝的Bufio會很有幫助。

 

如果大量的時間消耗在GC容器,那麼程式要麼分配了大量的短暫臨時的物件,要麼堆疊的空間非常小以致垃圾回收收集變得非常頻繁。通過檢視垃圾收集追蹤器和記憶體分析器這兩部分可以得到一些優化的建議。

溫馨提示:當前CPU分析器不能工作於darwin

溫馨提示:在windows系統上你需要安裝Cygwin, Perl和Graphviz才能生成svg/web簡介。

溫馨提示:在linux系統上你也可以嘗試PERF系統分析器。它不能解開Go的棧,但它可以獲得cgo或者SWIG的程式碼和kernel核心的快照並解開。所以它對於洞悉本地/kernel核心的效能瓶頸非常有幫助

記憶體分析器

記憶體分析器展示了哪些函式申請了堆記憶體。你可以通過熟悉的途徑來收集這些資訊,一如使用CPU分析器:和 'go test --memprofile', 以及通過 http://myserver:6060:/debug/pprof/heap的net/http/pprof 或者通過呼叫runtime/pprof.WriteHeapProfile

你僅僅可以視覺化描述收集器當前時間內的申請(預設下--inuse_space標識指向pprof),或者自程式啟動以來全部的申請(--alloc_space標識指向pprof)。前者對於在當前活動的程式通過net/http/pprof收集描述很有幫助,而後者則對在程式後端(否則你將會看到的幾乎都是空的描述)收集描述有幫助。

溫馨提示:記憶體分析器採取抽樣的方式,也就是說,它僅僅從一些記憶體分配的子集中收集資訊。有可能對一個物件的取樣與被取樣物件的大小成比例。你可以通過使用go test --memprofilerate標識,或者通過程式啟動時 的執行配置中的MemProfileRate變數來改變調整這個取樣的比例。如果比例為1,則會導致全部申請的資訊都會被收集,但是這樣的話將會使得執行變慢。預設的取樣比例是每512KB的記憶體申請就取樣一次。

       

你同樣可以將分配的位元組數或者分配的物件數形象化(分別是以--inuse/alloc_space和--inuse/alloc_objects為標誌)。分析器傾向於在效能分析中對較大的物件取樣。但是需要注意的是大的物件會影響記憶體消耗和垃圾回收時間,大量的小的記憶體分配會影響執行速度(某種程度上也會影響垃圾回收時間)。所以最好同時考慮它們。

物件可以是持續的也可以是瞬時的。如果你在程式開始的時候需要分配幾個大的持續物件,它們很有可能能被分析器取樣(因為它們比較大)這些物件會影響記憶體消耗量和垃圾回收時間,但它們不會影響正常的執行速度(在它們上沒有記憶體管理操作)。另一方面,如果你有大量持續期很短的物件,它們幾乎不會表現在曲線中(如果你使用預設的--inuse_space模式)。但它們的確顯著影響執行速度,因為它們被不斷地分配和釋放。所以再說一遍,最好同時考慮這兩種型別的物件。

       

所以,大體上,如果你想減小記憶體消耗量,那麼你需要檢視程式正常執行時--inuse_space收集的概要。如果你想提升程式的執行速度,就要檢視在程式特徵執行時間後或程式結束之後--alloc_objects收集的概要。

報告間隔時間由幾個標誌控制,--functions讓pprof報告在函式等級(預設)。--lines使pprof報告基於程式碼行等級,如果關鍵函式分佈在不同的程式碼行上,這將變得很有用。同樣還有--addresses和--files選項, 分別定位到精確的指令地址等級和檔案等級。

還有一個對記憶體概要很有用的選項,你可以直接在瀏覽器中檢視它(需要你匯入net/http/pprof包)。你開啟http://myserver:6060/debug/pprof/heap?debug=1就會看到堆概要,如下:

heap profile: 4: 266528 [123: 11284472] @ heap/1048576
1: 262144 [4: 376832] @ 0x28d9f 0x2a201 0x2a28a 0x2624d 0x26188 0x94ca3 0x94a0b 0x17add6 0x17ae9f 0x1069d3 0xfe911 0xf0a3e 0xf0d22 0x21a70
#    0x2a201    cnew+0xc1    runtime/malloc.goc:718
#    0x2a28a    runtime.cnewarray+0x3a            runtime/malloc.goc:731
#    0x2624d    makeslice1+0x4d                runtime/slice.c:57
#    0x26188    runtime.makeslice+0x98            runtime/slice.c:38
#    0x94ca3    bytes.makeSlice+0x63            bytes/buffer.go:191
#    0x94a0b    bytes.(*Buffer).ReadFrom+0xcb        bytes/buffer.go:163
#    0x17add6    io/ioutil.readAll+0x156            io/ioutil/ioutil.go:32
#    0x17ae9f    io/ioutil.ReadAll+0x3f            io/ioutil/ioutil.go:41
#    0x1069d3    godoc/vfs.ReadFile+0x133            godoc/vfs/vfs.go:44
#    0xfe911    godoc.func·023+0x471            godoc/meta.go:80
#    0xf0a3e    godoc.(*Corpus).updateMetadata+0x9e        godoc/meta.go:101
#    0xf0d22    godoc.(*Corpus).refreshMetadataLoop+0x42    godoc/meta.go:141

2: 4096 [2: 4096] @ 0x28d9f 0x29059 0x1d252 0x1d450 0x106993 0xf1225 0xe1489 0xfbcad 0x21a70
#    0x1d252    newdefer+0x112                runtime/panic.c:49
#    0x1d450    runtime.deferproc+0x10            runtime/panic.c:132
#    0x106993    godoc/vfs.ReadFile+0xf3            godoc/vfs/vfs.go:43
#    0xf1225    godoc.(*Corpus).parseFile+0x75        godoc/parser.go:20
#    0xe1489    godoc.(*treeBuilder).newDirTree+0x8e9    godoc/dirtrees.go:108
#    0xfbcad    godoc.func·002+0x15d            godoc/dirtrees.go:100

每個條目開頭的數字("1: 262144 [4: 376832]")分別表示目前存活的物件,存活物件佔據的記憶體, 分配物件的個數和所有分配物件佔據的記憶體總量。

優化工作經常和特定應用程式相關,但也有一些普遍建議。

1. 將小物件組合成大物件。比如, 將 *bytes.Buffer 結構體成員替換為bytes。緩衝區 (你可以預分配然後通過呼叫bytes.Buffer.Grow為寫做準備) 。這將減少很多記憶體分配(更快)並且減緩垃圾回收器的壓力(更快的垃圾回收) 。

2. 離開宣告作用域的區域性變數促進堆分配。編譯器不能保證這些變數擁有相同的生命週期,因此為他們分別分配空間。所以你也可以對區域性變數使用上述的建議。比如:將

for k, v := range m {
   k, v := k, v   // copy for capturing by the goroutine
   go func() {
       // use k and v
   }()
}

替換為:

for k, v := range m {
   x := struct{ k, v string }{k, v}   // copy for capturing by the goroutine
   go func() {
       // use x.k and x.v
   }()
}

這就將兩次記憶體分配替換為了一次。然而,這樣的優化方式會影響程式碼的可讀性,因此要合理地使用它。

3. 組合記憶體分配的一個特殊情形是分片陣列預分配。如果你清楚一個特定的分片的大小,你可以給末尾陣列進行預分配:

type X struct {
    buf      []byte
    bufArray [16]byte // Buf usually does not grow beyond 16 bytes.
}

func MakeX() *X {
    x := &X{}
    // Preinitialize buf with the backing array.
    x.buf = x.bufArray[:0]
    return x
}

4. 儘可能使用小資料型別。比如用int8代替int。

5. 不包含任何指標的物件(注意 strings,slices,maps 和 chans 包含隱含指標)不會被垃圾回收器掃描到。比如,1GB 的分片實際上不會影響垃圾回收時間。因此如果你刪除被頻繁使用的物件指標,它會對垃圾回收時間造成影響。一些建議:使用索引替換指標,將物件分割為其中之一不含指標的兩部分。

6. 使用釋放列表來重用臨時物件,減少記憶體分配。標準庫包含的 sync.Pool 型別可以實現垃圾回收期間多次重用同一個物件。然而需要注意的是,對於任何手動記憶體管理的方案來說,不正確地使用sync.Pool 會導致 use-after-free bug。

你也可以使用Garbage Collector Trace(見後文)來獲取更深層次的記憶體問題。

阻塞分析器

阻塞分析器展示了goroutine在等待同步原語(包括計時器通道)被阻塞的位置。你可以用類似CPU分析器的方法來收集這些資訊:通過'go test --blockprofile'net/http/pprof(經由h ttp://myserver:6060:/debug/pprof/block) 或者呼叫 runtime/pprof.Lookup("block").WriteTo

值得警示的是,阻塞分析器預設未啟用。'go test --blockprofile' 將為你自動啟用它。然而,如果你使用net/http/pprof 或者 runtime/pprof,你就需要手動啟用它(否則分析器將不會被載入)。通過呼叫 runtime.SetBlockProfileRate 來啟用阻塞分析器。SetBlockProfileRate 控制著由阻塞分析器報告的goroutine阻塞事件的比率。分析器力求取樣出每指定微秒數內,一個阻塞事件的阻塞平均數。要使分析器記錄每個阻塞事件,將比率設為1。

如果一個函式包含了幾個阻塞操作而且並沒有哪一個明顯地佔有阻塞優勢,那就在pprof中使用--lines標誌。

注意:並非所有的阻塞都是不利的。當一個goroutine阻塞時,底層的工作執行緒就會簡單地轉換到另一個goroutine。所以Go並行環境下的阻塞 與非並行環境下的mutex的阻塞是有很大不同的(例如典型的C++或Java執行緒庫,當發生阻塞時會引起執行緒空載和高昂的執行緒切換)。為了讓你感受一 下,我們來看幾個例子。

 在 time.Ticker上發生的阻塞通常是可行的,如果一個goroutine阻塞Ticker超過十秒,你將會在profile中看到有十秒的阻塞,這 是很好的。發生在sync.WaitGroup上的阻塞經常也是可以的,例如,一個任務需要十秒,等待WaitGroup完成的goroutine會在 profile中生成十秒的阻塞。發生在sync.Cond上的阻塞可好可壞,取決於情況不同。消費者在通道阻塞表明生產者緩慢或不工作。生產者在通道阻塞,表明消費者緩慢,但這通常也是可以的。在基於通道的訊號量發生阻塞,表明了限制在這個訊號量上的goroutine的數量。發生在sync.Mutex或sync.RWMutex上的阻塞通常是不利的。你可以在視覺化過程中,在pprof中使用--ignore標誌來從profile中排除已知的無關阻塞。

goroutine的阻塞會導致兩個消極的後果:

  1. 程式與處理器之間不成比例,原因是缺乏工作。排程器追蹤工具可以幫助確定這種情況。

  2. 過多的goroutine阻塞/解除阻塞消耗了CPU時間。CPU分析器可以幫助確定這種情況(在系統元件中找)。

這裡是一些通常的建議,可以幫助減少goroutine阻塞:

  1. 在生產者--消費者情景中使用充足的緩衝通道。無緩衝的通道實際上限制了程式的併發可用性。

  2. 針對於主要為讀取的工作量,使用sync.RWMutex而不是sync.Mutex。因為讀取操作在sync.RWMutex中從來不會阻塞其它的讀取操作。甚至是在實施級別。

  3. 在某些情況下,可以通過使用copy-on-write技術來完全移除互斥。如果受保護的資料結構很少被修改,可以為它製作一份副本,然後就可以這樣更新它:

type Config struct {
    Routes   map[string]net.Addr
    Backends []net.Addr
}

var config unsafe.Pointer  // actual type is *Config

// Worker goroutines use this function to obtain the current config.
func CurrentConfig() *Config {
    return (*Config)(atomic.LoadPointer(&config))
}

// Background goroutine periodically creates a new Config object
// as sets it as current using this function.
func UpdateConfig(cfg *Config) {
    atomic.StorePointer(&config, unsafe.Pointer(cfg))
}

這種模式可以防止在更新時阻塞的讀取對它的寫入。

4. 分割是另一種用於減少共享可變資料結構競爭和阻塞的通用技術。下面是一個展示如何分割雜湊表(hashmap)的例子:

type Partition struct {
    sync.RWMutex
    m map[string]string
}

const partCount = 64
var m [partCount]Partition

func Find(k string) string {
    idx := hash(k) % partCount
    part := &m[idx]
    part.RLock()
    v := part.m[k]
    part.RUnlock()
    return v
}

5. 本地快取和更新的批處理有助於減少對不可分解的資料結構的爭奪。下面你將看到如何分批處理向通道傳送的內容:

const CacheSize = 16

type Cache struct {
    buf [CacheSize]int
    pos int
}

func Send(c chan [CacheSize]int, cache *Cache, value int) {
    cache.buf[cache.pos] = value
    cache.pos++
    if cache.pos == CacheSize {
        c <- cache.buf
        cache.pos = 0
    }
}

這種技術並不僅限於通道,它還能用於批量更新對映(map)、批量分配等等。

6. 針對freelists,使用sync.Pool代替基於通道的或互斥保護的freelists,因為sync.Pool內部使用智慧技術來減少阻塞。

Go協程分析器

Go協程分析器簡單地提供給你當前程序中所有活躍的Go協程堆疊。它可以方便地除錯負載平衡問題(參考下面的排程器追蹤章節),或除錯死鎖。

這個配置僅僅對執行的程式有意義,所以去測試而不是揭露它. 你可以用net/http/pprof通過http://myserver:6060:/debug/pprof/goroutine來收集配置,並將之形象化為svg/pdf或通過呼叫runtime/pprof.Lookup("goroutine").WriteTo形象化。但最有用的方式是在你的瀏覽器中鍵入http://myserver:6060:/debug/pprof/goroutine?debug=2,它將會給出與程式崩潰時相同的符號化的堆疊。

需要注意的是:Go協程“syscall”將會消耗一個OS執行緒,而其他的Go協程則不會(除了名為runtime.LockOSThread的Go協程,不幸的是,它在配置中是不可見的)。同樣需要注意的是在“IO wait”狀態的Go協程同樣不會消耗執行緒,他們停駐在非阻塞的網路輪詢器(通常稍後使用epoll/kqueue/GetQueuedCompletionStatus來喚醒Go協程)。

垃圾收集器追蹤

除了效能分析工具以外,還有另外幾種工具可用——追蹤器。它們可以追蹤垃圾回收,記憶體分配和goroutine排程狀態。要啟用垃圾回收器(GC)追蹤你需要將GODEBUG=gctrace=1加入環境變數,再執行程式:

$ GODEBUG=gctrace=1 ./myserver

然後程式在執行中會輸出類似結果:

gc9(2): 12+1+744+8 us, 2 -> 10 MB, 108615 (593983-485368) objects, 4825/3620/0 sweeps, 0(0) handoff, 6(91) steal, 16/1/0 yields
gc10(2): 12+6769+767+3 us, 1 -> 1 MB, 4222 (593983-589761) objects, 4825/0/1898 sweeps, 0(0) handoff, 6(93) steal, 16/10/2 yields
gc11(2): 799+3+2050+3 us, 1 -> 69 MB, 831819 (1484009-652190) objects, 4825/691/0 sweeps, 0(0) handoff, 5(105) steal, 16/1/0 yields

來看看這些數字的意思。每個GC輸出一行。第一個數字("gc9")是GC的編號(這是從程式開始後的第九個GC),在括號中的數字("(2)")是參與GC的工作執行緒的編號。隨後的四個數字("12+1+744+8 us")分別是工作執行緒完成GC的stop-the-world, sweeping, marking和waiting時間,單位是微秒。接下來的兩個數字("2 -> 10 MB")表示前一個GC過後的存活堆大小和當前GC開始前完整的堆(包括垃圾)的大小。再接下來的三個數字 ("108615 (593983-485368) objects")是堆中的物件總數(包括垃圾)和和分配的記憶體總數以及空閒記憶體總數。後面的三個數字("4825/3620/0 sweeps")表示清理階段(對於前一個GC):總共有4825個儲存器容量,3620立即或在後臺清除,0個在stop-the-world階段清除(剩餘的是沒有使用的容量)。再後面的四個數字("0(0) handoff, 6(91) steal")表示在平行的標誌階段的負載平衡:0個切換操作(0個物件被切換)和六個steal 操作(91個物件被竊取)最後的三個數字("16/1/0 yields")表示平行標誌階段的係數:在等候其它執行緒的過程中共有十七個yield操作。

     

GC 是 mark-and-sweep 型別。總的 GC 可以表示成:

Tgc = Tseq + Tmark + Tsweep

這裡的 Tseq 是停止使用者的 goroutine 和做一些準備活動(通常很小)需要的時間;Tmark 是堆標記時間,標記發生在所有使用者 goroutine 停止時,因此可以顯著地影響處理的延遲;Tsweep 是堆清除時間,清除通常與正常的程式運行同時發生,所以對延遲來說是不太關鍵的。

標記時間大概可以表示成:

Tmark = C1*Nlive + C2*MEMlive_ptr + C3*Nlive_ptr

這裡的 Nlive 是垃圾回收過程中堆中的活動物件的數量,MEMlive_ptr 是帶有指標的活動物件佔據的記憶體總量,Nlive_ptr 是活動物件中的指標數量。

清除時間大概可以表示成:

Tsweep = C4*MEMtotal + C5*MEMgarbage

這裡的 MEMtotal 是堆記憶體的總量,MEMgarbage 是堆中的垃圾總量。

       

下一次垃圾回收發生在程式被分配了一塊與其當前所用記憶體成比例的額外記憶體時。這個比例通常是由 GOGC 的環境變數(預設值是100)控制的。如果 GOGC=100,而且程式使用了 4M 堆記憶體,當程式使用達到 8M 時,執行時(runtime)就會再次觸發垃圾回收器。這使垃圾回收的消耗與分配的消耗保持線性比例。調整 GOGC,會改變線性常數和使用的額外記憶體的總量。

只有清除是依賴於堆總量的,且清除與正常的程式運行同時發生。如果你可以承受額外的記憶體開銷,設定 GOGC 到以一個較高的值(200, 300, 500,等)是有意義的。例如,GOGC=300 可以在延遲相同的情況下減小垃圾回收開銷高達原來的二分之一(但會佔用兩倍大的堆)。

GC 是並行的,而且一般在並行硬體上具有良好可擴充套件性。所以給 GOMAXPROCS 設定較高的值是有意義的,就算是對連續的程式來說也能夠提高垃圾回收速度。但是,要注意,目前垃圾回收器執行緒的數量被限制在 8 個以內。

     

記憶體分配器跟蹤

記憶體分配器跟蹤只是簡單地將所有的記憶體分配和釋放操作轉儲到控制檯。通過設定環境變數“GODEBUG=allocfreetrace=1”就可以開啟該功能。輸出看起來像下面的內容:

tracealloc(0xc208062500, 0x100, array of parse.Node)
goroutine 16 [running]:
runtime.mallocgc(0x100, 0x3eb7c1, 0x0)
    runtime/malloc.goc:190 +0x145 fp=0xc2080b39f8
runtime.growslice(0x31f840, 0xc208060700, 0x8, 0x8, 0x1, 0x0, 0x0, 0x0)
    runtime/slice.goc:76 +0xbb fp=0xc2080b3a90
text/template/parse.(*Tree).parse(0xc2080820e0, 0xc208023620, 0x0, 0x0)
    text/template/parse/parse.go:289 +0x549 fp=0xc2080b3c50
...

tracefree(0xc208002d80, 0x120)
goroutine 16 [running]:
runtime.MSpan_Sweep(0x73b080)
       runtime/mgc0.c:1880 +0x514 fp=0xc20804b8f0
runtime.MCentral_CacheSpan(0x69c858)
       runtime/mcentral.c:48 +0x2b5 fp=0xc20804b920
runtime.MCache_Refill(0x737000, 0xc200000012)
       runtime/mcache.c:78 +0x119 fp=0xc20804b950
...

跟蹤資訊包括記憶體塊地址、大小、型別、執行程式ID和堆疊蹤跡。它可能更有助於除錯,但也可以給記憶體分配優化提供非常詳細的資訊。

排程器追蹤

排程器追蹤可以提供對 goroutine 排程的動態行為的內視,並且允許除錯負載平衡和可擴充套件性問題。要啟用排程器追蹤,可以帶有環境變數 GODEBUG=schedtrace=1000 來執行程式(這個值的意思是輸入的週期,單位 ms,這種情況下是每秒一次):

$ GODEBUG=schedtrace=1000 ./myserver

程式在執行過程中將會輸出類似結果:

SCHED 1004ms: gomaxprocs=4 idleprocs=0 threads=11 idlethreads=4 runqueue=8 [0 1 0 3]
SCHED 2005ms: gomaxprocs=4 idleprocs=0 threads=11 idlethreads=5 runqueue=6 [1 5 4 0]
SCHED 3008ms: gomaxprocs=4 idleprocs=0 threads=11 idlethreads=4 runqueue=10 [2 2 2 1]

第一個數字("1004ms")是從程式開始後的時間。Gomaxprocs 是當前的 GOMAXPROCS 值。 Idleprocs 是空載的處理器數(剩下的在執行 Go 程式碼)。Threads 是排程器產生的工作執行緒總數(執行緒有三種狀態:執行 Go 程式碼(gomaxprocs-idleprocs),執行 syscalls/cgocalls,閒置)。Idlethreads是閒置的工作執行緒數。Runqueue 是執行的 goroutine 的全域性佇列長度。方括號中的數字("[0 1 0 3]")是可執行的 goroutine 的前處理器佇列的長度。全域性和區域性佇列的長度總和表示執行中可用的 goroutine 的總數。

       

注意:你可以隨意組合追蹤器,如:GODEBUG = gctrace = 1,allocfreetrace = 1,schedtrace = 1000。

注意:同樣有詳細的排程器追蹤,你可以這樣啟用它:GODEBUG = schedtrace = 1000,scheddetail = 1。它將會輸出每一個 goroutine、工作執行緒和處理器的詳細資訊。我們將不會在這裡討論它的格式,因為它主要是給排程器開發者使用;你可以在這裡src/pkg/runtime/proc.c找到它的詳細資訊。

當一個程式不與 GOMAXPROCS 成線性比例和/或沒有消耗 100% 的 CPU 時間,排程器追蹤就顯得非常有用。理想的情況是:所有的處理器都在忙碌地執行 Go 程式碼,執行緒數合理,所有佇列都有充足的任務且任務是合理均勻的分佈的:

gomaxprocs=8 idleprocs=0 threads=40 idlethreads=5 runqueue=10 [20 20 20 20 20 20 20 20]

       

不好的情況是上面所列的東西並沒有完全達到。例如下面這個演示,沒有足夠的任務來保持所有的處理器繁忙:

gomaxprocs=8 idleprocs=6 threads=40 idlethreads=30 runqueue=0 [0 2 0 0 0 1 0 0]

注意:這裡使用作業系統提供的實際CPU利用率作為最終的標準。在 Unix 系作業系統中是 top 命令。在 Windows 系統中是工作管理員。

你可以使用 goroutine 分析器來了解哪些 goroutine 塊處於任務短缺狀態。注意,只要所有的處理器處於忙綠狀態,負載失衡就不是最壞的,它只會導致適度的負載平衡開銷。

       

記憶體統計

Go 執行時可以通過 runtime.ReadMemStats 函式提供粗糙的記憶體統計。這個統計同樣可以通過 http://myserver:6060/debug/pprof/heap?debug=1  底部的net/http/pprof提供。統計資料,點選此處

一些值得關注的地方是:

1. HeapAlloc - 當前堆大小。

2. HeapSys - 總的堆大小。

3. HeapObjects - 堆中物件的總數。

4. HeapReleased - 釋放到作業系統中的記憶體;如果記憶體超過五分鐘沒有使用,執行時將會把它釋放到作業系統中,你可以通過 runtime/debug.FreeOSMemory 來強制改變這個過程。

5. Sys - 作業系統分配的總記憶體。

6. Sys-HeapReleased - 程式的有效記憶體消耗。

7. StackSys - goroutine 棧的記憶體消耗(注意:一些棧是從堆中分配的,因此沒有計入這裡,不幸的是,沒有辦法得到棧的總大小(https://code.google.com/p/go/issues/detail?id=7468))。

8. MSpanSys/MCacheSys/BuckHashSys/GCSys/OtherSys - 執行時為各種輔助用途分配的記憶體;它們沒什麼好關注的,除非過高的話。

9. PauseNs - 最後一次垃圾回收的持續時間。

       

堆傾卸器

最後一個可用的工具是堆傾卸器,它可以將整個堆的狀態寫入一個檔案中,留作以後進行探索。它有助於識別記憶體洩露,並能夠洞悉程式的記憶體消耗。
首先,你需要使用函式runtime/debug.WriteHeapDump函式編寫傾卸器(dump):

 f, err := os.Create("heapdump")
 if err != nil { ... }
 debug.WriteHeapDump(f.Fd())

然後,你既可以將堆以圖形化的表現形式儲存為.dot檔案,也可以將它轉換為hprof格式。為了將它儲存為.dot檔案,你需要執行以下指令:

$ go get github.com/randall77/hprof/dumptodot
$ dumptodot heapdump mybinary > heap.dot

最後,使用Graphviz工具開啟heap.dot檔案。
為了將堆轉換成hprof格式,需要執行以下指令:

$ go get github.com/randall77/hprof/dumptohprof
$ dumptohprof heapdump heap.hprof
$ jhat heap.hprof

最後,將瀏覽器導航到http://localhost:7000。

結束語

優化是一個開放的問題,你可以使用很多簡單的方法來提高效能。然而,有時優化需要對程式進行完整地重新架構。但我們希望這些工具能夠成為你工具箱中一個有價值的新增成員,至少你可以使用它們分析並理解到底發生了什麼。

剖析Go程式》是一個很好的教程,它講解了如何利用CPU和記憶體分析器來優化簡單的程式。