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了。