golang trace view 视图详解

大家好，我是蓝胖子，在 golang 中可以使用 go pprof 的工具对 golang 程序进行性能分析，其中通过 go trace 命令生成的 trace view 视图对于我们分析系统延迟十分有帮助，鉴于当前对 trace view 视图的介绍还是很少，在粗略的看过 trace 统计原理后，我将对这部分做比较详细的介绍。

trace view 视图简介

在 go 代码里，我们可以通过 trace.Start 和 trace.Stop 方法开启和关闭 trace 统计，之后我们会得到一个 trace 文件，可以用 go tool trace 命令打开它·。

go tool trace -http=:8080  trace799152559

在浏览器的打开界面，可以看到 trace view 视图包含了几个维度的统计信息。

view trace 和 goroutine analysis 都是时间线的视图，不过观看的角度不同，view trace 是从 processor(Gpm 模型中的 p) 角度，goroutine analysis 则是从协程角度。

接着是各种类型的 profile 视图，包含 Network,Sync block,syscall block,scheduler latancy ，这些都可以用于分析系统延迟。

然后是用户自定义的埋点统计，由于本节主要是看原生的 trace view 视图含义，所以可以先略去这部分。

接着是 minimum mutator utilization 的视图，它可以用于分析垃圾回收对应用程序的影响。因为协程在分配内存时，在某些条件下也会触发垃圾回收，这将导致这部分时间内，协程不能执行用户程序逻辑，所以这个视图能够看到 cpu 用了多少时间在执行业务程序，多少时间用于垃圾回收。

接下来，我们仔细分析下各部分视图的含义。

view trace

如上图所示，整个 view trace 分为两个部分，stats 和 procs 部分。

stats

stats 部分统计了在时间线上协程，线程数量，以及堆栈大小的变化情况。

当点击某个一栏数据时，还会显示统计详情，比如点击时间线上线程这一栏，

如上图所示，trace view 视图最下方会出现当前时刻，处于运行状态和系统调用状态的线程数量。

procs

stats 部分比较好理解，我们再来看看 procs 部分，首先来看下 GC 这一栏。

GC 这一栏也就是视图中时间线上蓝色这一段表示程序在这段时间内，在进行垃圾回收。注意垃圾回收并不是全过程都会 STW 的，所以在 GC 这段时间，应用程序还是会对外提供服务的。并且点击蓝色区域，在视图下方还会显示 GC 开始的堆栈。

注意: golang 的垃圾回收除了定时扫描回收内存，还会在分配内存时，判断正在执行的协程是否需要执行垃圾回收逻辑，如果需要，则会执行 gcStart 的逻辑，mallocgc 就是 golang 进行内存分配的函数，所以你可以看到图中的 gc 正是由于当前协程分配内存才触发执行的，并且同一时期，只能有一个协程执行 gcStart 逻辑。

接着简单说下 Network 和 syscall 事件，它们在时间线上的点都是解除阻塞时的时间点。

然后来看 proc 这一栏，proc 代表的是 processor ，它数量一般与 cpu 核心数相同，也可以通过 GOMAXPROCS 设置其数量，协程需要放到 proc 队里里进行调度执行，proc 的时间线上显示的则是各个协程在其上的运行时间。放大 trace 视图后会看的更加明显。如下图所示:

trace 视图中，按 w 是放大，s 是缩小，a 是左移，d 是右移。

这里其实要特别注意的是 Outgoing flow 并不是直接导致协程在 p 队列上被切走的事件，实际上导致协程被切走的事件是阻塞事件，Outgoing flow 指的是阻塞事件之后被唤醒的那个时候的事件埋点。

实际上，当前的 trace view 视图绘制的时间线不会对阻塞事件进行绘制，只会对 EvGoUnblock 事件进行绘制（具体为啥这样设计，我也不知道了🙅🏻‍♀️）不过从协程离开 p 队列时的堆栈也足够说明协程被切走的原因了。

goroutine analysis

接着我们来看下 trace 文件中对协程信息的分析。

点击 goroutine analysis，出现下面的截图:

左边是协程创建时候的堆栈，右边 N 代码在这行代码上一共创建了多少个协程。随便选择一行点进去，可以出现下面的截图,

如上图所示，有各种的 profile graph，这里是对下面所有协程进行统一分析得到的 graph 图 ，分别是:

Network Wait Time(网络调用时等待，直到数据可达时被唤醒)

Sync Block Time(mutex，channel，wait.Group 产生的阻塞)

Blocking Syscall Time(系统调用产生的阻塞)

Scheduler Wait Time(协程阻塞后被唤醒并不会立马执行，而是在队列里等待被调度，这个时间就是等待被调度的时间)

而最下面的表格则是每个协程在这些维度上的消耗时间,这里要注意下两个 gc 相关的时间只有 GC sweeping 才会阻塞协程 ，GC sweeping 指的是协程在清除回收内存时的处理时间，而 GC pause 指的是采样过程中整个 gc 的时长，这一列每个协程都是一样的。

请注意，GC 过程中只有发送 STW 时才会让协程阻塞。

profile graph

关于 trcace 分析数据 除了像刚刚的特定堆栈产生的协程做各种延迟维度的分析，trace 界面还提供了一个看所有协程的延迟维度的 profile graph, 两者的原理都是一致的，只是后者原数据多一些。

拿其中一个维度 Scheduler Wait Time 的 graph 举例:

指向每个函数框的箭头都携带了一个时间，例如 273.31us，它代表 函数 servserv.init.func1 函数等待协程调度的等待时间，注意这个时间不包含它的子函数的时间。时间越大，函数框越大，所以，你在看此类的图的时候，找最大的框就能发现延迟所在。

Minimum mutator utilization

最后我们来看下 Minimum mutator utilization 这个视图。这个视图能够观测到垃圾回收对应用程序的影响。

如上图所示，纵坐标表示应用除 gc 外，占用 cpu 的比例。值越高，说明应用得到的 cpu 资源越多，gc 影响越小，最大值是 1 表示 100%得到 cpu 资源。图中，最后应用 cpu 占用率达到了 100%，可以暂时不用去管 gc 方面的影响。如果发现图中 cpu 资源长时间不能涨上去，则说明程序受 gc 影响比较大，应该对 gc 进行优化，像下面这种情况就应该优化 gc 了。