本文简单介绍 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 ,我们不断对图放大,可以看到:
![6e4898092a3901dfbd91050796a86d06.png](https://i-blog.csdnimg.cn/blog_migrate/c8c991c8534b9baed05a98feea5d5c5e.png)
图中右侧syscalls 里面是GC, 网络,以及多个cpu核的执行情况 (8核), 可以看到有一些 goroutine 被触发核执行,比如:
1. create 触发了writeLoop,请求操作。然后异步等待网络返回
2. gc 的标记操作。
下面是web请求到数据,从epoll 中触发,然后readLoop协程响应,直接触发main.create 的协程得到执行。
![b29ffe1bb7eee70d5c7f4f4a2e5b0cb0.png](https://i-blog.csdnimg.cn/blog_migrate/45f89c636705192d9193845ec27b35ba.png)
当然我们也可以筛选协程做具体分析。
从 Goroutine analysis 进入,选择具体的协程进行分析:
![46beda887f72ed0393cf6fd556f4949e.png](https://i-blog.csdnimg.cn/blog_migrate/1acb4e65e05eb2ce7a9bc1a0a6aa79f9.png)
我们选择对 main.create 的协程做分析(这个协程略复杂,可以分析的东西比较多)
![30058aa600d96816b0d3eac91a92ad81.png](https://i-blog.csdnimg.cn/blog_migrate/254161c6c6fdfff53eab93aa11f1529f.png)
可以从图中看出,network 唤醒 readLoop 协程,进而readLoop 又通知了main.create 协程。(这里右侧是具体的goroutine)
![ca0f6cfd16758cbdbc7f44ee07325fdf.png](https://i-blog.csdnimg.cn/blog_migrate/57dbd9430b5700131d66bfa6aedd6c09.png)
当然,我们也可以选择 main.convert goroutine。可以看出协程被main.create 唤醒了(由于给chan 提供了数据)
![f1c4762773680017c9335653107e91ec.png](https://i-blog.csdnimg.cn/blog_migrate/ac521a13cb5ff1a399fcfb47b84a8bd8.png)
除了可以分析goroutine 调度之外,还可以做网络阻塞分析,异步阻塞分析,系统调度阻塞分析,协程调度阻塞分析(下图)
![7cc591f60b471088afe952841da323d7.png](https://i-blog.csdnimg.cn/blog_migrate/1a41adb67949287cd4744c938c384978.png)
自定义 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操作)
![aa88a7009e84f386328967c4513f1a30.png](https://i-blog.csdnimg.cn/blog_migrate/276c45eea33662045341e205c5d5b3ec.png)
从图中可以看出,在2ms之后,可利用的cpu逐步上升,直到接近100%.所以gc 毫无压力。
重点提醒
必须用chrome,并且高版本不行。我使用的是76.
trace 的文件都比较大,几分钟可能上百兆,所以网络一定要好,或者使用本机做验证。
goroutine调度图中:w 放大, s 缩小, a 左移, d 右移
推荐阅读
喜欢本文的朋友,欢迎关注“Go语言中文网”:
![3be812be379d8da8d06d0ec8e9d89863.png](https://i-blog.csdnimg.cn/blog_migrate/209ea71b69dcce8b8e7102e0aec043f3.jpeg)
Go语言中文网启用微信学习交流群,欢迎加微信:274768166,投稿亦欢迎