golang性能分析之trace

ppp.go

package main

import (
	"os"
	"runtime/trace"
)

func main() {
    f, _ := os.OpenFile("trace.out", os.O_APPEND|os.O_CREATE|os.O_RDWR, os.ModePerm)
	trace.Start(f)
	defer trace.Stop()

	ch := make(chan string)
	go func() {
		ch <- "EDDYCJY"
	}()

	<-ch
}

go run ppp.go

go tool trace -http=localhost:8080 trace.out
2021/07/14 16:22:38 Parsing trace...
2021/07/14 16:22:38 Splitting trace...
2021/07/14 16:22:38 Opening browser. Trace viewer is listening on http://127.0.0.1:8080

http://127.0.0.1:8080

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 利用率

Scheduler latency profile

我们一般先查看 Scheduler latency profile，我们能通过 Graph 看到整体的调用开销情况，如下：

Goroutine analysis

我们能通过这个功能看到整个运行过程中，每个函数块有多少个有 Goroutine 在跑，并且观察每个的 Goroutine 的运行开销都花费在哪个阶段。如下：

点击每一项可以查看具体明细

同时也可以看到当前 Goroutine 在整个调用耗时中的占比，以及 GC 清扫和 GC 暂停等待的一些开销。如果你觉得还不够，可以把图表下载下来分析，相当于把整个 Goroutine 运行时掰开来看了，这块能够很好的帮助我们对 Goroutine 运行阶段做一个的剖析，可以得知到底慢哪，然后再决定下一步的排查方向。如下：

名称	含义	耗时
Execution Time	执行时间	3140ns
Network Wait Time	网络等待时间	0ns
Sync Block Time	同步阻塞时间	0ns
Blocking Syscall Time	调用阻塞时间	0ns
Scheduler Wait Time	调度等待时间	14ns
GC Sweeping	GC 清扫	0ns
GC Pause	GC 暂停	0ns

View trace

在对当前程序的 Goroutine 运行分布有了初步了解后，我们再通过 “查看跟踪” 看看之间的关联性，如下：

这个跟踪图粗略一看，相信有的小伙伴会比较懵逼，我们可以依据注解一块块查看，如下：

1. 时间线：显示执行的时间单元，根据时间维度的不同可以调整区间，具体可执行 shift + ? 查看帮助手册。
2. 堆：显示执行期间的内存分配和释放情况。
3. 协程：显示在执行期间的每个 Goroutine 运行阶段有多少个协程在运行，其包含 GC 等待（GCWaiting）、可运行（Runnable）、运行中（Running）这三种状态。
4. OS 线程：显示在执行期间有多少个线程在运行，其包含正在调用 Syscall（InSyscall）、运行中（Running）这两种状态。
5. 虚拟处理器：每个虚拟处理器显示一行，虚拟处理器的数量一般默认为系统内核数。
6. 协程和事件：显示在每个虚拟处理器上有什么 Goroutine 正在运行，而连线行为代表事件关联。

以 Goroutines 为例来看这个图。

点击红框的位置，下面会出来一些信息。

表示协程的三个状态，以及各个状态下有几个协程。上面格子的高度就是个数，颜色就是不同状态。Heap和Threads也是一样的看。

对于 PROCS ，可以点击对应的块，下面会显示具体信息。

解释如下：

• Start：开始时间
• Wall Duration：持续时间
• Self Time：执行时间
• Start Stack Trace：开始时的堆栈信息
• End Stack Trace：结束时的堆栈信息
• Incoming flow：输入流
• Outgoing flow：输出流
• Preceding events：之前的事件
• Following events：之后的事件
• All connected：所有连接的事件

对于真是的项目中往往数据比较多，打开来是这样的

将鼠标放在要查看的点上，按住W不断放大（S为缩小），按住鼠标左键可左右拖动，比如此处我要看GC这一行，貌似只在7s的前面有一个，鼠标放在哪个蓝线处，放大之后，再点击它，下面就能看到具体信息

Network 这一行，每一个竖线都表示unblock事件，意思就是某个协程之前执行了IO操作而被挂起了，在这个时刻fd可读或可写，于是协程被唤醒了，所以这个竖线的下方关联着一个协程。我们将鼠标放在竖线上按W放大，直到下方的G可见，然后点击此竖线（不太好点），就能看到信息，然后我们将鼠标移到Following events后面的Link上，就能看到这种关系。通过events可以看到各个事件之间的联系（包括，unblock，通过go关键字创建协程，使用chan通信）。

我们也看到了 G1 下方也有好多竖线，它表示 G1 在此时发起了系统调用syscall，点击任意一个。

这个页面属于总览，东西太多，不好找，我们回到起始页面，点击Goroutine analysis来分析具体Goroutine

可鞥需要根据自身业务情况找一找了。

这里列出了G55以及与其相关的G，到此就需要慢慢查看了。

在生产环境中，我们可提前埋伏好_ "net/http/pprof"，然后由pprof来提个trace信息。

curl http://127.0.0.1:6060/debug/pprof/trace?seconds=20 > trace.out
go tool trace trace.out

然后通过查看是否由阻塞（Network blocking profile， Syscall blocking profile，Synchronization blocking profile），然后看看 View trace。

参考：

https://blog.csdn.net/u013474436/article/details/105232768/