gRPC的请求追踪神器go tool trace

gRPC的请求追踪

前言

我们来回顾一下之前分享的知识点：

• gRPC介绍

介绍了基本你的gRPC的使用方式，框架，交互方式等

• gRPC的认证

分享了gRPC的四种认证方式中重要的2种方式，有兴趣可以点击看看哦

• openssl 证书生成笔记（go 1.15版本以上）

整理了openssl 证书的生成，关键点已经高亮标注，值得一看

• gRPC的拦截器

gRPC生态中的中间件，主要是做统一认证工作，不必要在每一个接口中都写一次认证方式

文章中有分享gRPC的各种功能的中间件，有兴趣可以点击链接，大佬们还请不吝赐教

go tool trace

今天我们来介绍一下go的请求追踪，也就是说go Trace ，分享trace有如下几个原因：

• 学习完trace之后，你能够自己去实践，清晰的了解整个程序的调用栈
• 可以通过追踪器捕获大量信息，如图

• 可以更快的解决我们项目中的疑难杂症

我们或许都有这样的体会，自己思考明白，设计出来的程序，可以很清晰明了的将细节解释明白，对功能的增删改也是可以做到灵活应对。

可是让我们一下子去修改别人写的功能或模块的时候，很多时候会一脸懵逼，这也不敢动，那也不敢动，在不理解的情况下，有疑问，一定要问清楚原理和逻辑，否则搞不好就是线上问题。

如上情况，最重要的一个原因就是自己对当前模块/功能的熟悉程度，以及自己的思维模型是否可迁移。

总而言之，对程序，要有敬畏之心，好奇之心，持之以恒专研下去，要有解决问题的决心。

用go tool trace具体哪些地方合适，哪些地方不合适？

不合适

• 运行缓慢的函数，或者找到大部分CPU时间花费在哪里，术业有专攻，看CPU时间花费，是有专门的工具的 go tool pprof

合适

• 找出程序在一段时间内正在做什么
• go tool trace 可以通过 view trace链接提供的其他可视化功能，对于诊断争用问题帮助极大

开始写一个DEMO

GOMAXPROCS设置可以同时执行的cpu的最大数量，此处我们设置为 1 个

server.go

package main
import (
   "context"
   "fmt"
   "os"
   "runtime"
   "runtime/trace"
   "sync"
)
func main() {
   // 使用 GOMAXPROCS设置可以同时执行的cpu的最大数量 为 1 个
   runtime.GOMAXPROCS(1)
   f, _ := os.Create("myTrace.dat")
   defer f.Close()
   //开始跟踪，在跟踪时，跟踪将被缓冲并写入 一个我们指定的文件中
   _ = trace.Start(f)
   defer trace.Stop()
   // 咱们自定义一个任务
   ctx, task := trace.NewTask(context.Background(), "customerTask")
   defer task.End()
   var wg sync.WaitGroup
   wg.Add(10)
   for i := 0; i < 10; i++ {
      // 启动10个协程，模拟做任务
      go func(num string) {
         defer wg.Done()
         // 标记  num
         trace.WithRegion(ctx, num, func() {
            var sum, i int64
            // 模拟执行任务
            for ; i < 500000000; i++ {
               sum += i
            }
            fmt.Println(num, sum)
         })
      }(fmt.Sprintf("num_%02d", i))
   }
   wg.Wait()
}

操作步骤：

• 编译并运行会生成我们既定好的数据文件
• 通过go tool trace + myTrace.dat
• 浏览器会弹出trace的web页面，如下

View trace

可视化的web追踪页面

tag	说明
时间线	用于显示执行的时间单元，根据时间维度的不同可以调整区间，可以点击按钮 ，便可以在界面上拖拽时间线
堆	用于显示执行期间的内存分配和释放情况
协程	用于显示在执行期间的每个 Goroutine 运行阶段有多少个协程在运行，其包含 GC 等待（GCWaiting）、可运行（Runnable）、运行中（Running）这三种状态。
OS 线程	显示在执行期间有多少个线程在运行，其包含正在调用 Syscall（InSyscall）、运行中（Running)这两种状态。
虚拟处理器	每个虚拟处理器显示一行，虚拟处理器的数量一般默认为系统内核数。
协程和事件	显示在每个虚拟处理器上有什么 Goroutine 正在运行，而连线行为代表事件关联。

可以使用 shift + ? 唤出帮助手册

点击PROC颜色区域

可以看到该处理器此段时间再做什么事情，如图

**Event(s)**下方的 Preceding events 点击进去可以看到每一个调用栈的执行时间

用户自定义任务如何查看？

• User-defined tasks
• 点击Count
• goroutine view
• 点击颜色区域

即可看到此段时间的调用栈，开始时间，结束时间，以及用户定义的任务开了多少个协程等等

User-defined tasks

点击Count

点击goroutine view

点击颜色区域

即可看到此段时间具体在执行什么动作，具体的信息如下

用户自定义区域如何查看呢？

与上述查看用户自定义任务的方式大同小异，如下

• User-defined regions
• 点击具体的Count

User-defined regions

点击具体的Count

即可查看到此协程的总共耗时，网络拥塞，同步阻塞，系统调用阻塞，调度等待，垃圾回收扫描，垃圾回收暂停的相关参数信息

那么某一些关键的goroutine被阻止运行时，可能会有延迟问题，大概的原因相信大家应该有些谱了吧

• 系统调用时被阻塞;
• 被共享内存阻塞（通道/互斥等）
• 调度程序没有按照我们所期望的频率运行协程
• 被runtime系统（例如GC）阻塞

正好上述原因的追踪都可以使用go tool trace 识别到 ，对于我们追踪问题，查询问题原理起了很好的助力作用

好了，本次就到这里，下一次分享 gRPC的HTTP网关，

技术是开放的，我们的心态，更应是开放的。拥抱变化，向阳而生，努力向前行。

我是小魔童哪吒，欢迎点赞关注收藏，下次见~