golang - Profiling Go Programs 記錄(Part 3)

3. 正常結束 Goroutine

$ go tool pprof ./gb heap-6438-1.pprof
(pprof) top10
Total: 8.6 MB
     1.5  17.8%  17.8%      3.0  35.3% main.(*Benchmark).Run
     1.5  17.8%  35.6%      1.5  17.8% main.(*Monitor).Run
     1.5  17.8%  53.4%      1.5  17.8% main.NewBenchmark
     1.5  17.5%  70.9%      1.5  17.5% net/textproto.MIMEHeader.Set
     1.0  11.7%  82.5%      1.0  11.7% bufio.NewReaderSize
     1.0  11.7%  94.2%      1.0  11.7% bufio.NewWriterSize
     0.5   5.8% 100.0%      0.5   5.8% newdefer
     0.0   0.0% 100.0%      0.5   5.8% bufio.(*Writer).Flush
     0.0   0.0% 100.0%      1.0  11.7% bufio.NewReader
     0.0   0.0% 100.0%      1.0  11.7% bufio.NewWriter

程式結束前仍有 8.6 MB 的 object 沒有被 GC 回收，但從搜集到的 heap 資訊看不出來有任何存在的 object reference 改從 goroutine 的 callstack 來追查是否為這些物件的 GC root

func main() {
    SetMemProfileRate(1) //(請參考第一篇附件 profilingtool.go)
    // ignored
    GC()    
    DumpHeap()
    PrintGCSummary()
    panic("show me the callstack")
}

在 Go 裡面只要不去攔截 panic 訊息就會把所有的 goroutine callstack 都印出來， 所以這裡降低 gorutine 的數量並且把輸出訊息導到 err.log 避免 terminal buffer 不足導致訊息被清掉

$ ./gb -c 2 -n 10 -k http://localhost/10k.dat 2>&1 | tee err.log
(略)

goroutine 1 [running]:
main.main()
    /home/brandon/workspaces/go/src/bench/gb/gb.go:66 +0x129

(略）
goroutine 9 [chan receive]:
main.(*HttpWorker).Run(0xc200098e00)
    /home/brandon/workspaces/go/src/bench/gb/http.go:37 +0x57
created by main.(*Benchmark).Run
    /home/brandon/workspaces/go/src/bench/gb/benchmark.go:39 +0xbb

goroutine 10 [chan receive]:
main.(*HttpWorker).Run(0xc200098e40)
    /home/brandon/workspaces/go/src/bench/gb/http.go:37 +0x57
created by main.(*Benchmark).Run
    /home/brandon/workspaces/go/src/bench/gb/benchmark.go:39 +0xbb
(略）

從 callstacks 可以看到 goroutine 9 / 10 的狀態都是 [chan receive] 並且停在 http.go:37

func (h *HttpWorker) Run() {
    <-h.start

    for job := range h.jobs { // L:37
        //ignored
        go h.send(job)
        //ignored
    }
}

狀況是 worker 在等 jobs channel 的 job，而 Benchmark 也已經結束不再傳送 job 給 jobs channel

修正方法

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

    for i := 0; i < b.config.requests; i++ {
        request, _ := NewHttpRequest(b.config)
        jobs <- request
    }
    close(jobs) // 已經不會再建立新 job 就可以關了, 別讓接收 job 的 httpworker 讓空的 jobs channel 給卡住

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

執行結果

$ ./gb -c 100 -n 200000 -k http://localhost/10k.dat
$ go tool pprof ./gb heap-32397-1.pprof
(pprof) top
Total: 0.2 MB
     0.0  30.6%  30.6%      0.0  30.6% runtime.cnew
     0.0  14.9%  45.5%      0.0  15.4% main.NewHttpWorker
     0.0  12.2%  57.8%      0.0  12.2% newdefer
     0.0   7.5%  65.3%      0.0   7.5% bufio.NewReaderSize
     0.0   7.5%  72.7%      0.0   7.5% bufio.NewWriterSize
     0.0   4.9%  77.6%      0.0   4.9% io/ioutil.blackHole
     0.0   4.8%  82.4%      0.0  24.8% net/http.(*Transport).dialConn
     0.0   3.5%  85.9%      0.0   3.5% runtime.malg
     0.0   1.2%  87.1%      0.0   1.2% net/textproto.(*Reader).ReadMIMEHeader
     0.0   1.1%  88.2%      0.0   1.6% flag.(*FlagSet).Var

程式離開前的記憶體從 8.6 MB 降到 0.2 MB