1. trace说明

在pprof的分析中，能够知道一段时间内的CPU占用、内存分配、协程堆栈信息。这些信息都是一段时间内数据的汇总，但是它们并没有提供整个周期内发生的事件，例如指定的Goroutines何时执行、执行了多长时间、什么时候陷入了堵塞、什么时候解除了堵塞、GC如何影响单个Goroutine的执行、STW中断花费的时间是否太长等。这就是在Go1.5之后推出的trace工具的强大之处，它提供了指定时间内程序发生的事件的完整信息，这些事件信息包括：

• 协程的创建、开始和结束。
• 协程的堵塞——系统调用、通道、锁。
• 网络I/O相关事件。
• 系统调用事件。
• 垃圾回收相关事件。

2. 收集trace样本

收集trace文件的方式和收集pprof特征文件的方式非常相似，有两种主要的方式

2.1 调用runtime/trace包

// 创建文件
file, _ := os.OpenFile("./trace.out", os.O_APPEND|os.O_CREATE, os.ModePerm)
// 开启
if err := trace.Start(file); err != nil {
    fmt.Println("trace start err ",err)
    return
}
// 关闭
defer trace.Stop()

2.2 调用net/http/pprof

net/http/pprof库中集成了trace的接口，下例获取30s内的trace事件并存储到trace.out文件中。

curl -o trace.out http://127.0.0.1:6060/debug/pprof/trace?seconds=30

2.3 在单元测试中使用-trace

//  trace.out:是生成的文件名  test/trace_test.go：是测试文件
go test -trace trace.out test/trace_test.go

3. 分析trace样本

分析trace样本,语法格式: go tool trace trace文件

3.1 第一步: 分析文件

# 分析文件trace2.out，会生成一个链接
➜ go tool trace trace2.out
2021/11/18 19:45:53 Parsing trace...
2021/11/18 19:45:53 Splitting trace...
2021/11/18 19:45:54 Opening browser. Trace viewer is listening on http://127.0.0.1:65154

3.2 第二步:在浏览器中打开

image.png

分析维度说明

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

4. View trace查看跟踪

4.1 数据栏总览

image.png

含义说明：

• 时间线: 显示执行的时间，上图可以看出程序整体运行时间在 0s~20s之间，可以用过放大查看具体某个时间点，运行情况。
• Goroutines: 显示在执行期间的每个Goroutine 运行阶段有多少个协程在运行，其包含 GC 等待（GCWaiting）、可运行（Runnable）、运行中（Running）这三种状态。
• 堆内存：包含当前堆使用量(Allocated)和下一次垃圾回收的目标大小(NextGC)统计。
• 系统线程：显示在执行期间有多少个线程在运行，其包含正在调用 Syscall（InSyscall）、运行中（Running）这两种状态。
• GC: 执行垃圾回收的次数和具体时间点，由上图可以看出每次执行GC时，堆内存都会下降。
• 逻辑处理器: 默认显示系统核心数量，可以通过runtime.GOMAXPROCS(n)来控制数量。

快捷键: w(放大)、s(缩小)、a(左移)、d(右移)

4.2 某一时刻协程整体运行情况

image.png

由上图可以看出，这个时刻(946.662607): 运行中的协程数量为2、可运行的协程数量为1、等待GC的协程为0

4.3 某一时刻堆内存

image.png

4.4 某一时刻系统线程

4.5 查看垃圾回收

1.单个垃圾回收

2.查看多个垃圾回收

选中多个垃圾回收，则可查看多个垃圾回收信息

3.部分协程功能说明

• proc start: 代表启动新线程或从系统调用恢复。

• proc stop: 代表线程在系统调用中被阻塞或线程退出。

• GC(dedicated、fractional、idle)：在标记阶段GC分为三种不同的 mark worker 模式; 它们代表着不同的专注程度，其中 dedicated 模式最专注，是完整的 GC 回收行为，fractional 只会干部分的 GC 行为，idle 最轻松。

• MARK ASSIST： 在分配内存过程中重新标记内存(mark the memory)的goroutine

• STW (sweep termination): 代表STW扫描阶段终止。

• STW (mark termination): 代表STW标记阶段终止。

• runtime.gcBgMarkWorker： 帮助标记内存的专用后台goroutine

• runtime.bgsweep: 执行垃圾清理的goroutine。

• runtime.bgscavenge: gc碎片清理的goroutine。

• syscall: 代表goroutine在进行系统调用。

• sysexit: 代表goroutine在syscall中被取消或阻塞。

4.6 查看具体协程运行信息

[图片上传失败...(image-297c6a-1680262407787)]

含义说明：

5. 协程分析(Goroutine analysis)

5.1 详情查看

5.2 字段说明

6.用户自定义任务

6.1 代码详情

package main

import (
    "context"
    "fmt"
    "os"
    "runtime/trace"
    "sync"
)
func main() {
    file, err := os.Create("./mytask.out")
    if err != nil {
        fmt.Printf("%v\n", err)
        return
    }
    defer file.Close()
    err = trace.Start(file)
    if err != nil {
        fmt.Printf("%v\n", err)
        return
    }
    defer trace.Stop()

    // 创建自定义任务
    ctx, task := trace.NewTask(context.Background(), "myTask")
    defer task.End()
    var wg sync.WaitGroup
    for i := 0; i < 10; i++ {
        gn := i
        // 启动协程
        wg.Add(1)
        go func() {
            defer wg.Done()
            trace.WithRegion(ctx, fmt.Sprintf("goroutine-%d",gn), func() {
                sum := 0
                for n := 0; n < 1000000; n++ {
                    sum = sum + n
                }
                fmt.Println("sum = ",sum)
            })
        }()
    }
    wg.Wait()
    fmt.Println("run ok!")
}

6.2 查看详情