Golang 效能測試 (3) 跟蹤刨析 golang trace

搬磚程式設計師帶你飛發表於2020-04-17
Golang

簡介

對於絕大部分服務，跟蹤刨析是用不到的。但是如果遇到了下面問題，可以不妨一試：

  • 懷疑哪個協程慢了
  • 系統呼叫有問題
  • 協程排程問題 (chan 互動、互斥鎖、訊號量等)
  • 懷疑是 gc (Garbage-Collect) 影響了服務效能
  • 網路阻塞
  • 等等

坦白的講，通過跟蹤刨析可以看到每個協程在某一時刻在幹什麼。

做跟蹤刨析，首先需要獲取trace 資料。可以通過程式碼中插入trace， 或者上節提到的通過pprof 下載即可。

Example

Code

下面通過程式碼直接插入的方式來獲取trace. 內容會涉及到網路請求，涉及協程非同步執行等。

package main

import (
	"io/ioutil"
	"math/rand"
	"net/http"
	"os"
	"runtime/trace"
	"strconv"
	"sync"
	"time"
)


var wg sync.WaitGroup
var httpClient = &http.Client{Timeout: 30 * time.Second}

func SleepSomeTime() time.Duration{
	return time.Microsecond * time.Duration(rand.Int()%1000)
}

func create(readChan chan int) {
	defer wg.Done()
	for i := 0; i < 500; i++ {
		readChan <- getBodySize()
		SleepSomeTime()
	}
	close(readChan)
}

func convert(readChan chan int, output chan string) {
	defer wg.Done()
	for readChan := range readChan {
		output <- strconv.Itoa(readChan)
		SleepSomeTime()
	}
	close(output)
}

func outputStr(output chan string) {
	defer wg.Done()
	for _ = range output {
		// do nothing
		SleepSomeTime()
	}
}

// 獲取taobao 頁面大小
func getBodySize() int {
	resp, _ := httpClient.Get("https://taobao.com")
	res, _ := ioutil.ReadAll(resp.Body)
	_ = resp.Body.Close()
	return len(res)
}

func run() {
	readChan, output := make(chan int), make(chan string)
	wg.Add(3)
	go create(readChan)
	go convert(readChan, output)
	go outputStr(output)
}

func main() {
	f, _ := os.Create("trace.out")
	defer f.Close()
	_ = trace.Start(f)
	defer trace.Stop()
	run()
	wg.Wait()
}

編譯，並執行，然後啟動trace;

[~/blog]$ go build trace_example.go 
[~/blog]$ ./trace_example
[~/blog]$ go tool trace -http=":8000" trace_example trace.out 
2020/04/15 17:34:48 Parsing trace...
2020/04/15 17:34:50 Splitting trace...
2020/04/15 17:34:51 Opening browser. Trace viewer is listening on http://0.0.0.0:8000

然後開啟瀏覽器，訪問8000 埠即可。

Trace 功能

其中:
View trace：檢視跟蹤 (按照時間分段，上面我的例子時間比較短，所以沒有分段)
Goroutine analysis：Goroutine 分析
Network blocking profile：網路阻塞概況
Synchronization blocking profile：同步阻塞概況
Syscall blocking profile：系統呼叫阻塞概況
Scheduler latency profile：排程延遲概況
User defined tasks：使用者自定義任務
User defined regions：使用者自定義區域
Minimum mutator utilization：最低 Mutator 利用率 （主要是GC 的評價標準, 暫時沒搞懂）

goroutine 排程分析

下圖包含了兩種事件：

  1. 網路相關 main.create 觸發網路寫的協程，網路寫操作的協程 writeLoop，然後等待網路返回。
  2. GC 相關操作

下面是web請求到資料，從epoll 中觸發，然後readLoop協程響應,直接觸發main.create 的協程得到執行。

當然我們也可以篩選協程做具體分析，從 Goroutine analysis 進入，選擇具體的協程進行分析：

我們選擇對 main.create 的協程做分析（這個協程略複雜，可以分析的東西比較多）

可以從圖中看出，network 喚醒 readLoop 協程，進而readLoop 又通知了main.create 協程。

當然，我們也可以選擇 main.convert 協程。可以看出協程被main.create 喚醒了（由於給chan 提供了資料）

除了可以分析goroutine 排程之外，還可以做網路阻塞分析，非同步阻塞分析，系統排程阻塞分析，協程排程阻塞分析（下圖）

自定義 Task 和 Region

當然，還可以指定task 和 Region 做分析，下面是官方舉的例子:

//filepath:  src/runtime/trace/trace.go
ctx, task := trace.NewTask(ctx, "makeCappuccino")
trace.Log(ctx, "orderID", orderID)

milk := make(chan bool)
espresso := make(chan bool)

go func() {
        trace.WithRegion(ctx, "steamMilk", steamMilk)
        milk <- true
}()
go func() {
        trace.WithRegion(ctx, "extractCoffee", extractCoffee)
        espresso <- true
}()
go func() {
        defer task.End() // When assemble is done, the order is complete.
        <-espresso
        <-milk
        trace.WithRegion(ctx, "mixMilkCoffee", mixMilkCoffee)
}()

MMU 圖

除此之外，還提供了Minimum Mutator Utilization 圖 (mmu 圖 )

mmu 圖，數軸是服務可以佔用cpu的百分比 (其他時間為gc操作)

從圖中可以看出，在2ms之後，可利用的cpu逐步上升，直到接近100%.所以gc 毫無壓力。

重點提醒

  1. 必須用chrome，並且高版本不行。我使用的是76.
  2. trace 的檔案都比較大，幾分鐘可能上百兆，所以網路一定要好，或者使用本機做驗證。
  3. 造作是 w 放大， s 縮小， a 左移， d 右移
  4. gc 的mmu 圖解釋 （備註下，還沒有來得及看）https://www.cs.cmu.edu/~guyb/papers/gc2001.pdf

相關文章