golang goroutine 通知_Golang 性能测试 (3) 协程追踪术

本文简单介绍 golang 如何做追踪刨析。

简介

对于绝大部分服务，追踪刨析是用不到的。但是如果遇到了下面问题，可以不妨一试：

• 怀疑哪个goroutine慢了
• 系统调用有问题
• goroutine调度问题 (chan 交互、互斥锁、信号量等)
• 怀疑是 gc (Garbage-Collect) 影响了服务性能
• 网络阻塞
• 等等

坦白的讲，通过追踪刨析可以看到每个 goroutine在某一时刻在干什么？

做追踪刨析，首先需要获取trace 数据。可以通过代码中插入trace， 或者上节提到的通过pprof 下载即可。

Example

先Coding，后解释

下面通过代码直接插入的方式来获取trace数据. 内容会涉及到网络请求，涉及协程异步执行等。

1234567891011121314151617181920212223242526272829303132333435363738394041424344454647484950515253545556575859606162636465666768697071

package mainimport ( "io/ioutil" "math/rand" "net/http" "os" "runtime/trace" "strconv" "sync" "time")var wg sync.WaitGroupvar 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 SleepSomeTime() } close(readChan)}func convert(readChan chan int, output chan string) { defer wg.Done() for readChan := range readChan { output 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() { // 讲trace数据输出到trace.out f, _ := os.Create("trace.out") defer f.Close() // trace 的开启和停止 _ = trace.Start(f) defer trace.Stop() run() wg.Wait()}

编译，并执行，然后启动trace。其中 trace.out 就是生成的trace.out

123456

$ go build trace_example.go$ ./trace_example$ go tool trace -http=":8000" trace_example trace.out2020/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

下面介绍Trace 的功能。

Trace 功能

在执行后，访问8000端口，就能得到下面的页面：

其中: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 利用率 

goroutine 调度分析

打开 view trace ,我们不断对图放大，可以看到：

图中右侧syscalls 里面是GC, 网络，以及多个cpu核的执行情况 (8核), 可以看到有一些 goroutine 被触发核执行，比如：

   1. create 触发了writeLoop，请求操作。然后异步等待网络返回

   2. gc 的标记操作。

下面是web请求到数据，从epoll 中触发，然后readLoop协程响应,直接触发main.create 的协程得到执行。

当然我们也可以筛选协程做具体分析。

从 Goroutine analysis 进入，选择具体的协程进行分析：

我们选择对 main.create 的协程做分析(这个协程略复杂，可以分析的东西比较多)

可以从图中看出，network 唤醒 readLoop 协程，进而readLoop 又通知了main.create 协程。(这里右侧是具体的goroutine)

当然，我们也可以选择 main.convert  goroutine。可以看出协程被main.create 唤醒了(由于给chan 提供了数据)

除了可以分析goroutine 调度之外，还可以做网络阻塞分析，异步阻塞分析，系统调度阻塞分析，协程调度阻塞分析(下图)

自定义 Task 和 Region

当然，还可以指定task 和 Region 做分析，下面是官方举的例子:

123456789101112131415161718192021

//filepath: src/runtime/trace/trace.goctx, 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. trace.WithRegion(ctx, "mixMilkCoffee", mixMilkCoffee)}()

MMU 图

除此之外，还提供了Minimum Mutator Utilization 图 (mmu 图 )

mmu 图，数轴是服务可以占用cpu的百分比 (其他时间为gc操作)

从图中可以看出，在2ms之后，可利用的cpu逐步上升，直到接近100%.所以gc 毫无压力。

重点提醒

1. 必须用chrome，并且高版本不行。我使用的是76.
2. trace 的文件都比较大，几分钟可能上百兆，所以网络一定要好，或者使用本机做验证。
3. goroutine调度图中：w 放大， s 缩小， a 左移， d 右移

推荐阅读

• Golang性能测试(2)—性能分析

喜欢本文的朋友，欢迎关注“Go语言中文网”：

Go语言中文网启用微信学习交流群，欢迎加微信：274768166，投稿亦欢迎