如何分析golang程式的記憶體使用情況
本文同步釋出於:如何分析golang程式的記憶體使用情況 | yoko blog
前言
本篇文章介紹如何分析golang程式的記憶體使用情況。包含以下幾種方法的介紹:
GODEBUG='gctrace=1'
注意,本篇文章前後有關聯,需要順序閱讀。
從十來行的demo開始
package main import ( "log" "runtime" "time" ) func f() { container := make([]int, 8) log.Println("> loop.") // slice會動態擴容,用它來做堆記憶體的申請 for i := 0; i < 32*1000*1000; i++ { container = append(container, i) } log.Println("< loop.") // container在f函式執行完畢後不再使用 } func main() { log.Println("start.") f() log.Println("force gc.") runtime.GC() // 呼叫強制gc函式 log.Println("done.") time.Sleep(1 * time.Hour) // 保持程式不退出 }
在我的centos上編譯並執行
$go build -o snippet_mem && ./snippet_mem
列印如下資訊:
2019/04/06 14:23:16 start. 2019/04/06 14:23:16 > loop. 2019/04/06 14:23:17 < loop. 2019/04/06 14:23:17 force gc. 2019/04/06 14:23:18 done.
使用top命令檢視snippet_mem程序的記憶體RSS佔用為470M。
$top -p $(pidof snippet_mem)
分析:
直觀上來說,這個程式在f()函式執行完後,切片的記憶體應該被釋放,不應該佔用470M那麼大。
下面讓我們使用一些手段來分析程式的記憶體使用情況。
GODEBUG中的gctrace
我們在執行demo程式之前新增環境變數GODEBUG='gctrace=1'
來跟蹤列印垃圾回收器資訊
$go build -o snippet_mem && GODEBUG='gctrace=1' ./snippet_mem
在分析demo程式的輸出資訊之前,先把gctrace輸出資訊的格式以及欄位的含義放前面,一會我們的分析要基於這部分內容。
gctrace輸出資訊的格式以及欄位的含義對應的官方文件:https://godoc.org/runtime 我對它做的翻譯如下: gctrace: 設定gctrace=1會使得垃圾回收器在每次回收時彙總所回收記憶體的大小以及耗時, 並將這些內容彙總成單行內容列印到標準錯誤輸出中。 這個單行內容的格式以後可能會發生變化。 目前它的格式: gc # @#s #%: #+#+# ms clock, #+#/#/#+# ms cpu, #->#-># MB, # MB goal, # P 各欄位的含義: gc #GC次數的編號,每次GC時遞增 @#s距離程式開始執行時的時間 #%GC佔用的執行時間百分比 #+...+#GC使用的時間 #->#-># MBGC開始,結束,以及當前活躍堆記憶體的大小,單位M # MB goal全域性堆記憶體大小 # P使用processor的數量 如果資訊以"(forced)"結尾,那麼這次GC是被runtime.GC()呼叫所觸發。 如果gctrace設定了任何大於0的值,還會在垃圾回收器將記憶體歸還給系統時列印一條彙總資訊。 這個將記憶體歸還給系統的操作叫做scavenging。 這個彙總資訊的格式以後可能會發生變化。 目前它的格式: scvg#: # MB releasedprinted only if non-zero scvg#: inuse: # idle: # sys: # released: # consumed: # (MB) 各欄位的含義: scvg#scavenge次數的變化,每次scavenge時遞增 inuse: #MB 垃圾回收器中使用的大小 idle: #MB 垃圾回收器中空閒等待歸還的大小 sys: #MB 垃圾回收器中系統對映記憶體的大小 released: #MB 歸還給系統的大小 consumed: #MB 從系統申請的大小
列印如下資訊:
2019/04/06 14:28:26 start. 2019/04/06 14:28:26 > loop. gc 1 @0.001s 0%: 0.005+0.92+0.004 ms clock, 0.011+0.027/0/0.13+0.009 ms cpu, 4->6->2 MB, 5 MB goal, 2 P gc 2 @0.003s 0%: 0.002+0.43+0.002 ms clock, 0.004+0.013/0/0.32+0.005 ms cpu, 5->5->1 MB, 6 MB goal, 2 P gc 3 @0.003s 1%: 0.002+0.47+0.003 ms clock, 0.004+0.027/0/0.44+0.006 ms cpu, 4->4->2 MB, 5 MB goal, 2 P gc 4 @0.004s 1%: 0.002+0.50+0.003 ms clock, 0.004+0.022/0/0.48+0.007 ms cpu, 5->5->2 MB, 6 MB goal, 2 P gc 5 @0.004s 1%: 0.001+1.2+0.003 ms clock, 0.003+0.070/0/1.1+0.006 ms cpu, 6->6->3 MB, 7 MB goal, 2 P gc 6 @0.006s 1%: 0.002+1.8+0.004 ms clock, 0.004+0.027/0.001/1.8+0.008 ms cpu, 8->8->4 MB, 9 MB goal, 2 P gc 7 @0.008s 1%: 0.002+2.4+0.005 ms clock, 0.005+0.042/0/2.4+0.010 ms cpu, 10->10->5 MB, 11 MB goal, 2 P gc 8 @0.010s 1%: 0.002+1.0+0.004 ms clock, 0.005+0.025/0/0.99+0.008 ms cpu, 12->12->6 MB, 13 MB goal, 2 P gc 9 @0.012s 1%: 0.011+1.8+0.005 ms clock, 0.022+0.025/0/1.7+0.010 ms cpu, 15->15->8 MB, 16 MB goal, 2 P gc 10 @0.014s 1%: 0.002+3.8+0.004 ms clock, 0.005+0.014/0/3.8+0.009 ms cpu, 19->19->10 MB, 20 MB goal, 2 P gc 11 @0.018s 1%: 0.003+2.0+0.004 ms clock, 0.006+0.026/0/2.0+0.008 ms cpu, 24->24->13 MB, 25 MB goal, 2 P gc 12 @0.020s 1%: 0.002+3.0+0.005 ms clock, 0.005+0.028/0/3.0+0.011 ms cpu, 30->30->16 MB, 31 MB goal, 2 P gc 13 @0.024s 0%: 0.003+9.0+0.004 ms clock, 0.006+0.028/0/9.0+0.009 ms cpu, 38->38->21 MB, 39 MB goal, 2 P gc 14 @0.033s 0%: 0.002+4.6+0.005 ms clock, 0.005+0.036/0/4.6+0.011 ms cpu, 47->47->26 MB, 48 MB goal, 2 P gc 15 @0.039s 0%: 0.003+13+0.004 ms clock, 0.007+0.024/0/13+0.009 ms cpu, 59->59->33 MB, 60 MB goal, 2 P gc 16 @0.053s 0%: 0.002+17+0.005 ms clock, 0.005+0.030/0.027/17+0.011 ms cpu, 74->74->41 MB, 75 MB goal, 2 P gc 17 @0.072s 0%: 0.049+29+0.004 ms clock, 0.098+0.015/0.091/29+0.009 ms cpu, 93->93->51 MB, 94 MB goal, 2 P gc 18 @0.103s 0%: 0.003+29+0.005 ms clock, 0.007+0.031/0.029/29+0.010 ms cpu, 116->116->64 MB, 117 MB goal, 2 P gc 19 @0.134s 0%: 0.003+41+0.004 ms clock, 0.006+0.016/0.030/41+0.009 ms cpu, 145->145->80 MB, 146 MB goal, 2 P gc 20 @0.178s 0%: 0.003+44+0.005 ms clock, 0.006+0.016/0.045/44+0.010 ms cpu, 181->181->101 MB, 182 MB goal, 2 P gc 21 @0.223s 0%: 0.003+55+0.004 ms clock, 0.006+0.015/0.044/55+0.008 ms cpu, 227->227->126 MB, 228 MB goal, 2 P gc 22 @0.281s 0%: 0.004+67+0.004 ms clock, 0.009+0.048/0.023/67+0.008 ms cpu, 284->284->157 MB, 285 MB goal, 2 P gc 23 @0.352s 0%: 0.004+90+0.005 ms clock, 0.008+0.035/0.042/90+0.011 ms cpu, 355->355->197 MB, 356 MB goal, 2 P 2019/04/06 14:28:27 < loop. 2019/04/06 14:28:27 force gc. gc 24 @0.446s 0%: 0.005+107+0.007 ms clock, 0.010+0.015/0.050/107+0.014 ms cpu, 444->444->0 MB, 445 MB goal, 2 P (forced) 2019/04/06 14:28:27 done. gc 25 @0.554s 0%: 0.077+0.071+0.002 ms clock, 0.15+0/0.078/0.036+0.004 ms cpu, 0->0->0 MB, 8 MB goal, 2 P (forced)
這裡順便一提,gc的列印資訊和demo程式log列印的資訊是並行往標準錯誤輸出列印的,所以可能會亂,上面所貼的列印資訊的倒數第3、4行是我自己手動重排了,重排前的資訊如下:
gc 24 @0.446s 0%: 2019/04/06 14:28:27 force gc. 0.005+107+0.007 ms clock, 0.010+0.015/0.050/107+0.014 ms cpu, 444->444->0 MB, 445 MB goal, 2 P (forced)
demo程式之後會每隔一段時間列印一些gc資訊,彙總如下:
GC forced gc 26 @120.562s 0%: 0.008+0.18+0.005 ms clock, 0.016+0/0.051/0.10+0.010 ms cpu, 0->0->0 MB, 8 MB goal, 2 P scvg0: inuse: 0, idle: 959, sys: 959, released: 447, consumed: 512 (MB) GC forced gc 27 @240.562s 0%: 0.005+0.19+0.005 ms clock, 0.010+0/0.063/0.13+0.010 ms cpu, 0->0->0 MB, 4 MB goal, 2 P GC forced scvg1: 512 MB released scvg1: inuse: 0, idle: 959, sys: 959, released: 959, consumed: 0 (MB) gc 28 @360.564s 0%: 0.007+0.099+0.004 ms clock, 0.014+0/0.036/0.13+0.008 ms cpu, 0->0->0 MB, 4 MB goal, 2 P GC forced gc 29 @480.565s 0%: 0.006+0.30+0.005 ms clock, 0.013+0/0.048/0.12+0.010 ms cpu, 0->0->0 MB, 4 MB goal, 2 P scvg2: 0 MB released scvg2: inuse: 0, idle: 959, sys: 959, released: 959, consumed: 0 (MB) GC forced gc 30 @600.566s 0%: 0.004+0.11+0.005 ms clock, 0.009+0/0.045/0.15+0.010 ms cpu, 0->0->0 MB, 4 MB goal, 2 P scvg3: inuse: 0, idle: 959, sys: 959, released: 959, consumed: 0 (MB) GC forced gc 31 @720.566s 0%: 0.004+0.081+0.004 ms clock, 0.009+0/0.024/0.10+0.008 ms cpu, 0->0->0 MB, 4 MB goal, 2 P GC forced gc 32 @840.567s 0%: 0.006+0.12+0.005 ms clock, 0.012+0/0.039/0.17+0.010 ms cpu, 0->0->0 MB, 4 MB goal, 2 P scvg4: inuse: 0, idle: 959, sys: 959, released: 959, consumed: 0 (MB)
分析:
先看在f()函式執行完後立即列印的gc 24
那行的資訊。444->444->0 MB, 445 MB goal
表示垃圾回收器已經把444M的記憶體標記為非活躍的記憶體。
再看0.1秒之後的gc 25
。0->0->0 MB, 8 MB goal
表示垃圾回收器中的全域性堆記憶體大小由445M下降為8M。
結論:在f()函式執行完後,demo程式中的切片容器所申請的堆空間都被垃圾回收器回收了。
但是此時top顯示記憶體依然佔用470M。
結論:垃圾回收器回收了應用層的記憶體後,(可能)並不會立即將記憶體歸還給系統。
接下來看scvg相關的資訊。該資訊在demo程式每執行一段時間後列印一次。
scvg0時consumed為512M。此時記憶體還沒有歸還給系統。
scvg1時consumed為0,並且scvg1的released=(scvg0 released + scvg0 consumed)
。此時記憶體已歸還給系統。
我們通過top命令檢視,記憶體佔用下降為38M。
之後列印的scvg資訊不再有變化。
結論:垃圾回收器在一段時間後,(可能)會將回收的記憶體歸還給系統。
到這裡,我們對GODEBUG中的gctrace的用法已經介紹完畢了。
實時上,我們最前面的疑問也解決了。
但是我們接下來依然會使用另外幾次方法來分析我們的domo程式。
runtime.ReadMemStats
我們稍微修改一下demo程式,在一些執行流程上以及f()函式執行完後每10秒使用runtime.ReadMemStats
獲取記憶體使用情況。
package main import ( "log" "runtime" "time" ) func traceMemStats() { var ms runtime.MemStats runtime.ReadMemStats(&ms) log.Printf("Alloc:%d(bytes) HeapIdle:%d(bytes) HeapReleased:%d(bytes)", ms.Alloc, ms.HeapIdle, ms.HeapReleased) } func f() { container := make([]int, 8) log.Println("> loop.") for i := 0; i < 32*1000*1000; i++ { container = append(container, i) if i == 16*1000*1000 { traceMemStats() } } log.Println("< loop.") } func main() { log.Println("start.") traceMemStats() f() traceMemStats() log.Println("force gc.") runtime.GC() log.Println("done.") traceMemStats() go func() { for { traceMemStats() time.Sleep(10 * time.Second) } }() time.Sleep(1 * time.Hour) }
列印如下資訊:
2019/04/06 17:37:52 start. 2019/04/06 17:37:52 Alloc:49328(bytes) HeapIdle:66494464(bytes) HeapReleased:0(bytes) 2019/04/06 17:37:52 > loop. 2019/04/06 17:37:52 Alloc:238510080(bytes) HeapIdle:364863488(bytes) HeapReleased:334856192(bytes) 2019/04/06 17:37:52 < loop. 2019/04/06 17:37:52 Alloc:207053496(bytes) HeapIdle:664731648(bytes) HeapReleased:396263424(bytes) 2019/04/06 17:37:52 force gc. 2019/04/06 17:37:52 done. 2019/04/06 17:37:52 Alloc:49864(bytes) HeapIdle:871768064(bytes) HeapReleased:396255232(bytes) 2019/04/06 17:37:52 Alloc:51056(bytes) HeapIdle:871727104(bytes) HeapReleased:396222464(bytes) // ... 省略部分日誌 2019/04/06 17:42:32 Alloc:52304(bytes) HeapIdle:871718912(bytes) HeapReleased:396214272(bytes) 2019/04/06 17:42:42 Alloc:52416(bytes) HeapIdle:871718912(bytes) HeapReleased:396214272(bytes) 2019/04/06 17:42:52 Alloc:52528(bytes) HeapIdle:871718912(bytes) HeapReleased:603217920(bytes) 2019/04/06 17:43:02 Alloc:52640(bytes) HeapIdle:871718912(bytes) HeapReleased:871653376(bytes) 2019/04/06 17:43:12 Alloc:52752(bytes) HeapIdle:871718912(bytes) HeapReleased:871653376(bytes) 2019/04/06 17:43:22 Alloc:52864(bytes) HeapIdle:871718912(bytes) HeapReleased:871653376(bytes)
可以看到,列印done.
之後那條trace資訊,Alloc已經下降,即記憶體已被垃圾回收器回收。在2019/04/06 17:42:52
和2019/04/06 17:43:02
的兩條trace資訊中,HeapReleased開始上升,即垃圾回收器把記憶體歸還給系統。距離列印done.
時有5分鐘時間間隔。
另外,MemStats還可以獲取其它哪些資訊以及欄位的含義可以參見官方文件:
http://golang.org/pkg/runtime/#MemStats使用pprof工具
在網頁上檢視記憶體使用情況,需在程式碼中新增兩行程式碼
import( "net/http" _ "net/http/pprof" ) go func() { log.Println(http.ListenAndServe("0.0.0.0:10000", nil)) }()
然後就可以使用瀏覽器開啟以下地址檢視記憶體資訊http://127.0.0.1:10000/debug/pprof/heap?debug=1
使用此方法,除了有MemStats的資訊,還有申請記憶體發生在哪些函式的資訊。
總結
golang的垃圾回收器在回收了應用層的記憶體後,有可能並不會立即將回收的記憶體歸還給作業系統。
如果我們要觀察應用層程式碼使用的記憶體大小,可以觀察Alloc
欄位。
如果我們要觀察程式從系統申請的記憶體以及歸還給系統的情況,可以觀察HeapIdle
和HeapReleased
欄位。
以上3種方法,都是獲取了程式的MemStats資訊。區別是:第一種完全不用修改程式,第二種可以在指定位置獲取資訊,第三種可以檢視具體哪些函式申請了記憶體。