Golang 性能測驗 (3) 跟蹤刨析 golang trace-有解無憂

簡介

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

懷疑哪個協程慢了
系統呼叫有問題
協程調度問題 (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 調度分析

下圖包含了兩種事件：

網路相關 main.create 觸發網路寫的協程，網路寫操作的協程 writeLoop，然后等待網路回傳，
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 毫無壓力，

重點提醒

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

轉載請註明出處，本文鏈接：https://www.uj5u.com/houduan/24399.html

標籤：Go

上一篇：Go語言可變引數

下一篇：Go語言的GPM調度器是什么？