Sitemap
Open in app

Sign in

Medium Logo
Write

Sign in

高效能 Golang 程式 — Execution tracer

Peter Lai
17 min readNov 7, 2020

--

前言

近期看到了 high-performance-go-workshop 這篇文章，作者分享很多調教 golang 程式效能的方式，覺得這篇文章寫的很清楚就來翻譯成中文，我也會將文章分成幾個部分翻譯，這篇是翻譯第五章 Execution Tracer

第二章效能比較（Benchmarking）的翻譯：高效能 Golang 程式 — 效能比較

第三章效能測量及分析（Performance Measurement and Profiling）的翻譯：高效能 Golang 程式 — 效能測量及分析

第四章編譯器優化（Compiler Optimizations）的翻譯：高效能 Golang 程式 — 編譯器優化

Execution Tracer

Execution Tracer 由 Dmitry Vyukov 開發，多年來都沒有文件記錄跟使用

與前面幾個章節提到的分析方法不同，execution tracer 集成在 Go runtime，因此了解 Go 程式在做什麼

我覺得看一段 pprof 的程式碼會更容易解釋 execution tracer 的功能以及為什麼很重要

examples/mandelbrot 裡面有產生 Mandelbrot sets 的範例程式碼，範例裡用的是 Francesc Campoy 的 mandelbrot

$ cd examples/mandelbrot
$ go build && ./mandelbrot

執行完後會產生這張圖

花了多久時間產生這張 1024x1024 的圖片？

我們可以用 time 指令知道共花了多久時間產生這張圖片

$ time ./mandelbrot
real 0m1.960s
user 0m1.915s
sys 0m0.026s

別用 time go run mandelbrot.go，這會把編譯程式的時間也計算進去

我們可以看到程式用了 1.9 秒產生這張圖片並寫進檔案

這樣夠快了嗎？還是我們能優化讓它執行更快嗎？

為了回答這些問題，其中一個方式可以透過 Go 內建的 pprof 來分析程式

分析程式

前面的章節有提到可以透過這兩種方式產生 pprof

  1. 使用 runtime/pprof
  2. 使用原作者封裝的 github.com/pkg/profile

runtime/pprof 要手動接比較多底層的 api，另一個則是已經封裝了函數可以直接呼叫

使用 runtime/pprof

我們可以在原來的程式加入這些程式碼，來啟用 CPU Profile

import "runtime/pprof"

func main() {
	pprof.StartCPUProfile(os.Stdout)
	defer pprof.StopCPUProfile()

因為直接寫進 Stdout，所以我們可以將顯示的結果寫入檔案（不寫進檔案的話會看到亂碼）

$ cd mandelbrot-runtime-pprof
$ go run mandelbrot.go > cpu.pprof

因為 CPU Profile 不會計算編譯的時間，所以可以直接用 go run 執行

使用 github.com/pkg/profile

前面用的方式很簡單，但可能會遇到以下幾個問題

  • 如果沒寫進檔案，命令列可能會顯示很多字元
  • 如果將其他資料寫進 os.Stdout 會破壞結果，例如使用 fmt.Println

建議可以將 pprof 的結果寫進檔案，當然開發者可以手動將結果寫進檔案，不過要記得要關閉檔案

也可以用作者寫的套件（已經將寫入檔案封裝在套件裡面）

import "github.com/pkg/profile"

func main() {
	defer profile.Start(profile.CPUProfile, profile.ProfilePath(".")).Stop()

執行後會看到

$ cd mandelbrot-pkg-profile
2020/11/07 10:38:41 profile: cpu profiling enabled, cpu.pprof
2020/11/07 10:38:43 profile: cpu profiling disabled, cpu.pprof

分析結果

我們可以用 go tool 讀取分析的檔案

$ go tool pprof cpu.pprof

如果比較喜歡網頁介面也可以用

$ go tool pprof -http=:8080 cpu.pprof

這篇文章就以命令列的結果為例

$ go tool pprof cpu.pprof
Type: cpu
Time: Nov 7, 2020 at 10:38am (CST)
Duration: 1.74s, Total samples = 1.50s (86.12%)
Entering interactive mode (type "help" for commands, "o" for options)

可以看到程式執行了 1.74 秒，pprof 總共用了 1.50 秒收集資料

讓我們用 top 排序一下

(pprof) top
Showing nodes accounting for 1.47s, 98.00% of 1.50s total
Showing top 10 nodes out of 56
      flat  flat%   sum%        cum   cum%
     0.63s 42.00% 42.00%      0.63s 42.00%  main.paint (inline)
     0.62s 41.33% 83.33%      1.26s 84.00%  main.fillPixel
     0.10s  6.67% 90.00%      0.10s  6.67%  runtime.madvise
     0.04s  2.67% 92.67%      0.04s  2.67%  compress/flate.(*compressor).findMatch
     0.02s  1.33% 94.00%      0.03s  2.00%  runtime.mallocgc
     0.02s  1.33% 95.33%      0.02s  1.33%  syscall.syscall
     0.01s  0.67% 96.00%      0.02s  1.33%  image/png.opaque
     0.01s  0.67% 96.67%      0.01s  0.67%  image/png.paeth
     0.01s  0.67% 97.33%      0.01s  0.67%  runtime.(*mspan).refillAllocCache
     0.01s  0.67% 98.00%      0.01s  0.67%  runtime.asyncPreempt

因為程式主要是在畫圖，所以 main.paint 佔用最多的 CPU 這是很正常，不過還是讓我們用 cummulative flag 來看看 main.paint 哪個地方使用這麼多時間

(pprof) top --cum
Showing nodes accounting for 1250ms, 83.33% of 1500ms total
Showing top 10 nodes out of 56
      flat  flat%   sum%        cum   cum%
         0     0%     0%     1380ms 92.00%  main.main
         0     0%     0%     1380ms 92.00%  runtime.main
     620ms 41.33% 41.33%     1260ms 84.00%  main.fillPixel
         0     0% 41.33%     1260ms 84.00%  main.seqFillImg
     630ms 42.00% 83.33%      630ms 42.00%  main.paint (inline)
         0     0% 83.33%      120ms  8.00%  image/png.(*Encoder).Encode
         0     0% 83.33%      120ms  8.00%  image/png.Encode (inline)
         0     0% 83.33%      120ms  8.00%  runtime.mstart
         0     0% 83.33%      100ms  6.67%  image/png.(*encoder).writeIDATs
         0     0% 83.33%      100ms  6.67%  image/png.(*encoder).writeImage

Tracing vs Profiling

上面的範例我們發無法從 Profiling 了解更多資訊，只能看到哪個地方執行比較久

現在我們來試試 execution tracer，只要將 mode 調整為 profile.TraceProfile

import "github.com/pkg/profile"

func main() {
	defer profile.Start(profile.TraceProfile, profile.ProfilePath(".")).Stop()

執行後會有產生 trace.out在資料夾

$ cd mandelbrot-tracer && go run mandelbrot.go
2020/11/07 10:58:20 profile: trace enabled, trace.out
2020/11/07 10:58:21 profile: trace disabled, trace.out

可以使用 Go 內建的工具檢視結果

$ go tool trace trace.out 
2020/11/07 11:01:00 Parsing trace...
2020/11/07 11:01:00 Splitting trace...
2020/11/07 11:01:00 Opening browser. Trace viewer is listening on http://127.0.0.1:51623

go tool trace 跟 go tool pprof 有點不同，go tool trace 會將原來的 execution trace 轉成

瀏覽器能用的資料

Analyzing the trace

點選 view trace 後可以發現這個程式只用了單核

func seqFillImg(m *img) {
	for i, row := range m.m {
		for j := range row {
			fillPixel(m, i, j)
		}
	}
}

這是因為原始碼中每個 sequence 會呼叫一次 fillPixel

一旦圖片產生了，execution 開始寫入 .png 檔案，會在 heap 上產生沒用的記憶體，因此 trace 開始改變，圖片可以看到 GC 作用的鋸齒形狀

trace profile 可以設定到毫秒的分辨率，這是用其它工具都無法做到的

go tool trace 注意事項

* 因為使用 Chrome 的 javascript debugging，所以只能在 Chrome 裡面使用（使用 Chromium 為核心的瀏覽器說不定都可以）

* 因為是 Google 的產品，所以有支援鍵盤，wasd 能夠調整上下左右（不確定）

* 瀏覽 traces 會使用很多記憶體，至少要有 8 GB 記憶體才夠

使用多個 CPU

Mandelbrot 是 embarassingly_parallel（平行化不會改善很多），每個 pixel 都可以獨立計算，我們試試看用 syncWaitGroup 以及 goroutine 分開運算

$ time ./mandelbrot -mode px
2020/11/07 14:09:27 profile: trace enabled, trace.out
2020/11/07 14:09:28 profile: trace disabled, trace.outreal 0m1.631s
user 0m6.126s
sys 0m1.725s

執行的時間沒有什麼改變，不過這次用了比較多的 user time（因為我們用了所有的 CPU，每一個的時間都是相同的）

讓我們來看看 trace 的結果，因為產生較多的 trace 資料，所以要等比較久網頁才會打開

  • 每次執行中間會有個 gap，那應該是 scheduler
  • 雖然用了四個核心，由於 fillPixel 是個工作量很小的函數，因此在 scheduler 用了蠻多時間（頻繁切換）

Batching up work

渲染每個 pixel 就用一個 goroutine 不符成本，接著我們試試看每一列用一個 goroutine

$ time ./mandelbrot -mode row
2020/11/07 14:39:12 profile: trace enabled, trace.out
2020/11/07 14:39:12 profile: trace disabled, trace.outreal 0m0.462s
user 0m1.668s
sys 0m0.026s

這次執行時間減少了一半，trace 的檔案也比較小

我們可以看到這次的 trace 有下面的改善

  • 可以看到一開始 goroutine 產生了約 1000 個，上面的範例產生了 10 ** 6 個
  • onePerRowFillImg 執行的比較久，使得 goroutine 能提早產生下個 work，這樣 scheduler 可以更有效的分配其他 goroutines

Using workers

讓我們試試看 workers

$ time ./mandelbrot -mode workers
2020/11/07 14:58:52 profile: trace enabled, trace.out
2020/11/07 14:58:56 profile: trace disabled, trace.outreal 0m4.147s
user 0m4.667s
sys 0m1.035s

可以看到執行時間變得很久，為什麼會這樣呢？

因為預設的 workers 只有一個，如果改用 12 個會比較好嗎（我的電腦是 12 核，所以就帶入 12）？

$ time ./mandelbrot -mode workers -workers 12
2020/11/07 15:02:59 profile: trace enabled, trace.out
2020/11/07 15:03:01 profile: trace disabled, trace.outreal 0m2.650s
user 0m8.754s
sys 0m2.030s

可以看到 user time 和 sys time 都更久（原文章 real time 也更久，但我這邊執行時沒有發生）

這是因為 workers 裡面用的 channel 是 unbuffered channel

  • The producer cannot send work until there is a worker ready to receive it.
  • Workers cannot receive work until there is someone ready to send, so they compete with each other when they are waiting.
  • The sender is not privileged, it cannot take priority over a worker that is already running.

我們可以看到這個範例裡 unbuffered channel 造成延遲，scheduler 裡有很多 start/stop 時間，並且在等待時可能會有 locks 和 mutexes，這也是 sys time 會比較高的原因

Using buffered channels

接著我們將 unbuffered channel 改為 buffered channel 看看會發生什麼事

$ cd mandelbrot-buffered && go build
$ time ./mandelbrot -mode workers -workers 12
2020/11/07 15:23:46 profile: trace enabled, trace.out
2020/11/07 15:23:47 profile: trace disabled, trace.outreal 0m0.772s
user 0m3.543s
sys 0m0.414s

可以看到跟前面 row 的範例結果相似，查看 trace 的結果可以發現

  • producer 不用等待 worker
  • worker 不用等待就可以快速取得下個 pixel 的資料

如果調整 nWorkersFillImg 每次 producer 推送一個 row 的資料（與前面第二個範例相同），結果會怎麼樣？

$ time ./mandelbrot -mode workers -workers 12
2020/11/07 15:29:54 profile: trace enabled, trace.out
2020/11/07 15:29:55 profile: trace disabled, trace.outreal 0m0.776s
user 0m1.800s
sys 0m0.026s

Mandelbrot microservice

現在是 2020，分析 Mandelbrots 沒有意義除非在網路上開啟一個無伺服器的微服務

因此，我們要試試 Mandelweb

$ go run mandelweb/mandelweb.go
2020/11/07 15:38:10 listening on http://127.0.0.1:8080/

Tracing 運行中的應用程式

前面的範例我們 trace 了整個程式，也發現 traces 瘩資料可以變得很多，如果要一直收集 traces 的資料會很難分析，而且 tracing 也會影響程式的執行速度

如果我們只想從執行中的程式收集一些 traces？別擔心，net/http/pprof 有提供想關的功能

透過 http 收集 traces

import _ "net/http/pprof"

import 之後 net/http/pprof 會在 http.DefaultServeMux 增加 tracinng/profiling 的路由（從 Go 1.5 後會有 trace profiler）

如果是使用 ServeMux，可能需要手動增加 pprof api 的端口

我們可以用 curl/wget 擷取 5 秒的執行結果

$ curl -o trace.out http://127.0.0.1:8080/debug/pprof/trace?seconds=5

增加伺服器的 load

分析一個 idle 的伺服器，可能不會有什麼效能問題，我們可以使用 hey by JBD

$ go get -u github.com/rakyll/hey

試試每秒 1 個請求

$ hey -c 1 -n 1000 -q 1 http://127.0.0.1:8080/mandelbrot

同時間，在另一個視窗收集 trace

$ curl -o trace.out http://127.0.0.1:8080/debug/pprof/trace?seconds=5

模擬伺服器超載

試試每秒 13 個請求（因為我的電腦是 12 核）

$ hey -c 13 -n 1000 -q 13 http://127.0.0.1:8080/mandelbrot

同時間，在另一個視窗收集 trace

$ curl -o trace.out http://127.0.0.1:8080/debug/pprof/trace?seconds=5

參考

High Performance Go Workshop

This is Hennessy's quote from Google Next 18 and his Turing Award lecture. His contention is yes, CPU performance is…

dave.cheney.net

The concurrent prime sieve is one of the first Go programs written.

Ivan Daniluk wrote a great post on visualising it.

Rhys Hiltner, Go’s execution tracer (dotGo 2016)

Rhys Hiltner, An Introduction to “go tool trace” (GopherCon 2017)

Dave Cheney, Seven ways to profile Go programs (GolangUK 2016)

Dave Cheney, High performance Go workshop]

Ivan Daniluk, Visualizing Concurrency in Go (GopherCon 2016)

Kavya Joshi, Understanding Channels (GopherCon 2017)

Francesc Campoy, Using the Go execution tracer

Golang
Performance
Execution Tracer

--

--

Peter Lai
Peter Lai

Written by Peter Lai

238 followers
204 following

github: https://github.com/sc0Vu

No responses yet

Help

Status

About

Careers

Press

Blog

Privacy

Rules

Terms

Text to speech