Apr 18, 2013

golang - Profiling Go Programs 記錄(Part 4)

4. 快取計算結果

第2與3項只修正 bug 但對效能沒有直接改善,以目前的觀測結果,程式向系統申請的記憶體用量還有點高(350M左右), 接著來檢查 GC 與 heap 狀況看哪些物件申請了這些記憶體

用 GOGCTRACE=1 讓 GO runtime 把 gclog 印出來,將印出的訊息傳給 log2csv 轉成 csv 檔案

$ GOGCTRACE=1 ./gb -c 100 -n 200000 -k http://localhost/10k.dat 2>&1 | log2csv -t -o gc.csv
unixtime,numgc,nproc,mark,sweep,cleanup,heap0,heap1,obj0,obj1,nmalloc,nfree,nhandoff,nhandoffcnt,nsteal,nstealcnt,nprocyield,nosyield,nsleep
1366278874.698135,1,1,0,0,0,0,0,24,26,27,1,0,0,0,0,0,0,0
1366278874.701761,2,2,1,0,0,2,2,608,518,642,124,0,0,5,31,22,4,0
1366278874.707143,3,2,4,0,0,4,4,993,985,1118,133,0,0,2,41,22,15,6
1366278874.725975,4,2,6,0,0,9,9,36182,36148,36317,169,6,187,2,78,70,24,17
1366278874.767119,5,2,13,0,0,18,18,113518,113518,113688,170,3,87,2,301,42,23,21
1366278874.837911,6,2,16,1,0,37,37,268246,268246,268417,171,4,93,2,48,54,20,11
1366278874.982132,7,2,35,2,0,75,75,577694,577694,577866,172,6,287,2,306,42,23,31
1366278875.267363,8,2,67,5,1,150,150,1196615,1196615,1196788,173,5,182,2,2063,32,23,11
1366278877.850924,9,2,64,35,8,301,154,2212070,1183694,2284625,1100931,8,502,13,16101,16,14,2
1366278879.561168,10,2,63,23,5,309,147,2233288,1119515,3411483,2291968,2,47,4,10961,32,16,13
1366278881.097839,11,2,70,40,2,294,139,2121182,1054221,4486980,3432759,2,17,4,17879,32,5,0
1366278882.543087,12,2,57,24,7,278,131,2000935,993438,5503542,4510104,1,2,3,9999,19,12,12
1366278883.873273,13,2,48,25,2,262,124,1888388,935583,6464524,5528941,3,152,2,10759,26,22,2
(略)

gc.csv 再用 gnuplot 將 csv 檔案裡的數據繪制成圖表 gnuplot-heap.p

$ gnuplot gnuplot-heap.p

看起來是程式開始申請了過量的記憶體,GC 清空後 runtime 也沒把多餘的空間再還給作業系統, 再分析 gc.csv 後找到大量申請時間約在第6-10次gc, 於程式啟動後第5秒的時候達到最大值

為了要找出開始大量申請空間的物件,下面的程式在第1秒與第7秒各 dump 一次 heap

func main() {
    SetMemProfileRate(1)
    go func() {
        time.Sleep(time.Duration(1) * time.Second)
        DumpHeap()
        time.Sleep(time.Duration(6) * time.Second)
        DumpHeap()
    }()
    // ignored
    PrintGCSummary()
}
$ ./gb -c 100 -n 200000 http://localhost/10k.dat
(略)
NumGC:56 Pause:113.57ms Pause(Avg):425.33ms Overhead:30.54% Alloc:22.53M Sys:662.14M Alloc(Rate):43.24M/s Histogram:996.58ms 1.07s 1.07s 

在 go tool pprof 加上 --base 顯示兩個 profile 相減後的數據

$ go tool pprof ./gb --base heap-19221-1.pprof heap-19221-2.pprof 
(pprof) top
Total: 74.3 MB
    35.6  47.9%  47.9%     35.6  47.9% net/textproto.MIMEHeader.Set
    26.3  35.4%  83.3%     37.1  50.0% net/http.NewRequest
    10.8  14.6%  97.9%     10.8  14.6% net/url.parse
     1.5   2.1% 100.0%      1.5   2.1% net/textproto.MIMEHeader.Add
     0.0   0.0% 100.0%      0.0   0.0% resizefintab
     0.0   0.0% 100.0%      0.0   0.0% itab
     0.0   0.0% 100.0%      0.0   0.0% os.NewFile
     0.0   0.0% 100.0%      0.0   0.0% concatstring
(pprof) top -cum
Total: 74.3 MB
     0.0   0.0%   0.0%     74.3 100.0% gosched0
     0.0   0.0%   0.0%     74.3 100.0% main.(*Benchmark).Run
     0.0   0.0%   0.0%     74.3 100.0% main.NewHttpRequest
     0.0   0.0%   0.0%     74.3 100.0% main.main
     0.0   0.0%   0.0%     74.3 100.0% main.startBenchmark
     0.0   0.0%   0.0%     74.3 100.0% runtime.main
    26.3  35.4%  35.4%     37.1  50.0% net/http.NewRequest
     0.0   0.0%  35.4%     35.6  47.9% net/http.Header.Set
    35.6  47.9%  83.3%     35.6  47.9% net/textproto.MIMEHeader.Set
     0.0   0.0%  83.3%     10.8  14.6% net/url.Parse

比較兩個 heap 過後,總共增加了 74.3 MB,從top -cum顯示這 74.3MB 100.0% 是 main.(*Benchmark).Run 底下產生的

(pprof) web main.\(\*Benchmark\).Run

SVG File

(pprof) list main.\(\*Benchmark\).Run
Total: 74.3 MB
ROUTINE ====================== main.(*Benchmark).Run in /home/brandon/workspaces/go/src/bench/gb/benchmark.go
   0.0   74.3 Total MB (flat / cumulative)
     .      .   27:     monitor := NewMonitor(config, collector, start, stop)
     .      .   28: 
     .      .   29:     return &Benchmark{config, collector, monitor, start, stop}
     .      .   30: }
     .      .   31: 
---
     .      .   32: func (b *Benchmark) Run() {
     .      .   33: 
     .      .   34:     go b.monitor.Run()
     .      .   35: 
     .      .   36:     jobs := make(chan *http.Request, b.config.requests)
     .      .   37: 
     .      .   38:     for i := 0; i < b.config.concurrency; i++ {
     .      .   39:         go NewHttpWorker(b.config, jobs, b.collector, b.start, b.stop).Run()
     .      .   40:     }
     .      .   41: 
     .      .   42:     for i := 0; i < b.config.requests; i++ {
     .   74.3   43:         newRequest, _ := NewHttpRequest(b.config)
     .      .   44:         jobs <- newRequest
     .      .   45:     }
     .      .   46:     close(jobs)
     .      .   47: 
     .      .   48:     close(b.start)
     .      .   49:     <-b.stop
     .      .   50: }
---
(pprof)

main.(*Benchmark).Run 的 L:43 NewHttpRequest 增加了 74.3 MB 的記憶體,從程式行為來分析,問題是L:42的迴圈在一開始就產生了所有 NewHttpRequest,另一個是 NewHttpRequest 是個昂貴的操作為了建立 http.NewRequest 衍生使用了 textproto.MIMEHeader.Set 與 net/url.parse

優化方法:複製 httpRequest 結果避免同樣的計算與空間浪費

func (b *Benchmark) Run() {

    go b.monitor.Run()

    jobs := make(chan *http.Request, b.config.requests)

    for i := 0; i < b.config.concurrency; i++ {
        go NewHttpWorker(b.config, jobs, b.collector, b.start, b.stop).Run()
    }
    base, _ := NewHttpRequest(b.config)
    for i := 0; i < b.config.requests; i++ {
        newRequest := CopyHttpRequest(b.config, base)
        jobs <- newRequest
    }
    close(jobs)

    close(b.start)
    <-b.stop
}

func CopyHttpRequest(config *Config, request *http.Request) *http.Request {

    if config.method == "POST" || config.method == "PUT" {
        newRequest := *request
        if newRequest.Body != nil {
            newRequest.Body = ioutil.NopCloser(bytes.NewReader(config.bodyContent))
        }
        return &newRequest
    } else {
        return request
    }

}

執行結果

$ ./gb -c 100 -n 200000 -k http://localhost/10k.dat
(略)
Document Path:          /10k.dat
Document Length:        10240 bytes

Concurrency Level:      100
Time taken for tests:   12.14 seconds
Complete requests:      200000
Failed requests:        0
HTML transferred:       2048000000 bytes
Requests per second:    16471.31 [#/sec] (mean)
Time per request:       6.071 [ms] (mean)
Time per request:       0.061 [ms] (mean, across all concurrent requests)
HTML Transfer rate:     164713.14 [Kbytes/sec] received

Connection Times (ms)
              min   mean[+/-sd] median  max
Total:        0         0   3.50    4   38

Percentage of the requests served within a certain time (ms)
 50%     4
 66%     5
 75%     7
 80%     7
 90%     10
 95%     12
 98%     14
 99%     17
 100%    38 (longest request)

NumGC:49 Pause:6.15ms Pause(Avg):7.52ms Overhead:3.00% Alloc:18.19M Sys:284.25M Alloc(Rate):64.70M/s Histogram:10.50ms 13.11ms 13.11ms
$ echo "  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND";  top -d 1 -b | grep gb
  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND
 9529 brandon   20   0  732m  20m 2860 S  29.7  0.1   0:00.30 gb
 9529 brandon   20   0  942m  23m 2864 S 103.6  0.1   0:01.35 gb
 9529 brandon   20   0 1016m  24m 2864 S 105.1  0.2   0:02.41 gb
 9529 brandon   20   0 1016m  24m 2864 S 103.5  0.2   0:03.46 gb
 9529 brandon   20   0 1088m  25m 2864 S 104.1  0.2   0:04.51 gb
 9529 brandon   20   0 1088m  25m 2864 S 104.0  0.2   0:05.56 gb
 9529 brandon   20   0 1088m  26m 2864 S 102.2  0.2   0:06.59 gb
 9529 brandon   20   0 1088m  26m 2864 S 103.8  0.2   0:07.64 gb
 9529 brandon   20   0 1160m  26m 2864 S 104.2  0.2   0:08.69 gb
 9529 brandon   20   0 1160m  26m 2864 S 105.1  0.2   0:09.75 gb
 9529 brandon   20   0 1160m  27m 2864 S 103.2  0.2   0:10.79 gb
 9529 brandon   20   0 1160m  27m 2864 S 103.1  0.2   0:11.83 gb

向系統申請記憶體終於在這次測試裡降下來(25MB vs 350MB),平均 GC 停頓時間也降低(7.52ms vs 40.91ms)

gc2.csv

Post a Comment