golang 协程追踪术

lpflpf · · 1441 次点击 · 开始浏览    置顶
这是一个创建于 的主题,其中的信息可能已经有所发展或是发生改变。

## 简介 对于绝大部分服务,跟踪刨析是用不到的。但是如果遇到了下面问题,可以不妨一试: - 怀疑哪个协程慢了 - 系统调用有问题 - 协程调度问题 (chan 交互、互斥锁、信号量等) - 怀疑是 gc (Garbage-Collect) 影响了服务性能 - 网络阻塞 - 等等 坦白的讲,通过跟踪刨析可以看到每个协程在某一时刻在干什么。 做跟踪刨析,首先需要获取trace 数据。可以通过代码中插入trace, 或者上节提到的通过pprof 下载即可。 ## Example ### Code 下面通过代码直接插入的方式来获取trace. 内容会涉及到网络请求,涉及协程异步执行等。 ```go 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; ```shell [lipengfei5@localhost ~/blog]$ go build trace_example.go [lipengfei5@localhost ~/blog]$ ./trace_example [lipengfei5@localhost ~/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 功能 ![trace_home.jpg](https://static.studygolang.com/200417/99e68feed3a524648aa6cdd35b4867ab.jpg) 其中: 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 相关操作 ![trace_net_request.jpg](https://static.studygolang.com/200417/9337d704654fe63f03894fbfb79f8c70.jpg) 下面是web请求到数据,从epoll 中触发,然后readLoop协程响应,直接触发main.create 的协程得到执行。 ![trace_read_from_network.jpg](https://static.studygolang.com/200417/432cb20d6f515f6e9cc053409e637d84.jpg) 当然我们也可以筛选协程做具体分析,从 Goroutine analysis 进入,选择具体的协程进行分析: ![trace_goroutines_home.jpg](https://static.studygolang.com/200417/1884bf52fff3839a9468da029c8fc0fc.jpg) 我们选择对 main.create 的协程做分析(这个协程略复杂,可以分析的东西比较多) ![trace_main_create_goroutine.jpg](https://static.studygolang.com/200417/8022dea10bf502c869b9875e38182050.jpg) 可以从图中看出,network 唤醒 readLoop 协程,进而readLoop 又通知了main.create 协程。 ![trace_main_create_goroutine_trace.jpg](https://static.studygolang.com/200417/57a0340484ac77f5fd2c38e2793330c4.jpg) 当然,我们也可以选择 main.convert 协程。可以看出协程被main.create 唤醒了(由于给chan 提供了数据) ![trace_main_convert_goroutine.jpg](https://static.studygolang.com/200417/c715051e50c1bf26b96dc7256e07c72a.jpg) 除了可以分析goroutine 调度之外,还可以做网络阻塞分析,异步阻塞分析,系统调度阻塞分析,协程调度阻塞分析(下图) ![trace_sched_goroutine.jpg](https://static.studygolang.com/200417/f618863be250b848e50081c0121cd64e.jpg) ### 自定义 Task 和 Region 当然,还可以指定task 和 Region 做分析,下面是官方举的例子: ```golang //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操作) ![trace_mmu.jpg](https://static.studygolang.com/200417/33f90c9cb8b5ebab59fbc3df6b04332b.jpg) 从图中可以看出,在2ms之后,可利用的cpu逐步上升,直到接近100%.所以gc 毫无压力。 ![weixin_logo.png](https://static.studygolang.com/200417/38f4c1f1949bdce0b416b9121f4b1602.png) ## 重点提醒 1. 必须用chrome,并且高版本不行。我使用的是76. 2. trace 的文件都比较大,几分钟可能上百兆,所以网络一定要好,或者使用本机做验证。 3. 造作是 w 放大, s 缩小, a 左移, d 右移 4. gc 的mmu 图解释 (备注下,还没有来得及看)https://www.cs.cmu.edu/~guyb/papers/gc2001.pdf

有疑问加站长微信联系(非本文作者)

入群交流(和以上内容无关):加入Go大咖交流群,或添加微信:liuxiaoyan-s 备注:入群;或加QQ群:692541889

1441 次点击  
加入收藏 微博
暂无回复
添加一条新回复 (您需要 登录 后才能回复 没有账号 ?)
  • 请尽量让自己的回复能够对别人有帮助
  • 支持 Markdown 格式, **粗体**、~~删除线~~、`单行代码`
  • 支持 @ 本站用户;支持表情(输入 : 提示),见 Emoji cheat sheet
  • 图片支持拖拽、截图粘贴等方式上传