本文简单介绍 golang 如何做追踪刨析。
简介
对于绝大部分服务,追踪刨析是用不到的。但是如果遇到了下面问题,可以不妨一试:
坦白的讲,通过追踪刨析可以看到每个
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 毫无压力。
重点提醒
必须用chrome,并且高版本不行。我使用的是76.
trace 的文件都比较大,几分钟可能上百兆,所以网络一定要好,或者使用本机做验证。
goroutine调度图中:w 放大, s 缩小, a 左移, d 右移
推荐阅读
喜欢本文的朋友,欢迎关注“Go语言中文网”:
Go语言中文网启用微信学习交流群,欢迎加微信:274768166,投稿亦欢迎