Go Execution Tracer工具使用

介绍

在Go工具链中，go tool pprof（与runtime/pprof或net/http/pprof联合使用）是一个基于采样（sampling）的性能剖析(profiing)辅助工具。它基于定时器对运行的go程序进行各种采样，包括诸如CPU时间、内存分配等方面。

但是go pprof也具有上面所说的基于采样的工具的不足，那就是采样的频度不足导致的精确性问题，在Go运行时内部，CPU分析使用操作系统计时器来定期（每秒约100次，即10ms一次）中断执行。在每个中断（也称为样本）上，它同时收集当时的调用堆栈。当为了实现更高频度采样时（比如微秒级别的采样），目前的go profile无法支持。

因此, Go语言提供了基于追踪（tracing）策略的工具，一旦开启trace，Go应用中发生的所有特定事件（event）便会被记录下来，并支持将其保存在文件中以备后续分析，这个工具由谷歌工程师Dmitry Vyukov提出设计方案并实现，并在Go 1.5版本发布时加入Go工具链，这个工具被称为Go Execution Tracer

在Dmitry Vyukov最初的设计中，他希望Tracer能为Go开发者提供至少如下的关于goroutine执行情况的信息：

• 与goroutine调度有关的事件信息：goroutine的创建、启动和结束；goroutine在同步原语（包括mutex、channel收发操作）上的阻塞与解锁。
• 与网络有关的事件：goroutine在网络I/O上的阻塞和解锁；
• 与系统调用有关的事件：goroutine进入系统调用与从系统调用返回；
• 与垃圾回收器有关的事件：GC的开始/停止，并发标记、清扫的开始/停止。

随着软件功能的不断演进, 当前Tracer分为了如下几个功能模块, 如下图:

功能页面.png

Tracer文件生成

Go语言提供了3种生成Tracer文件的方法

• runtime/trace.Start
• net/http/pprof package
• go test -trace

runtime/trace.Start 方法

runtime/trace包是整个Tracer的基础与核心, 所有生成Tracer文件的方法都是基于这个包实现的, 它的基本使用如下:

package main

import (
    "os"
    "runtime/trace"
)

func main() {
	//注意的是每次开启都要对应一个独立的文件, 重复的文件会报错, go Tracer是支持动态开启的, 所以可以灵活地控制其输出到不同的文件
	f, _ := os.Create("trace.out")
    defer f.Close()
    trace.Start(f)
    defer trace.Stop()
    
    // 下面是业务代码
    ... ...
}

我们通过trace.Start开启Tracer，并在程序结束时通过trace.Stop停止Tracer，Tracer收集到的数据输出到trace.out文件, Tracer支持动态开关, 生产环境可以采用这种方式，这样可以将Tracer带来的开销限制在最小范围。

net/http/pprof package 方法

如果一个Go应用通过net/http/pprof包提供对pprof采样的支持，那么我们就可以像获取cpu或heap profile数据那样，通过/debug/pprof/trace端点来开启Tracer并获取Tracer数据：

curl -s http://localhost:43000/debug/pprof/trace?seconds=10 > trace.out

go test -trace 方法

如果要在测试执行时开启Tracer，我们可以通过go test -trace来实现：

$go test -trace trace.out ./...

命令执行结束后，trace.out中便存储了测试执行过程中的Tracer数据，后续我们可以用go tool trace对其进行展示和分析。

Go Trace分析

package main

import (
	"fmt"
	pb "github.com/guirongguo/ghz_demo/proto"
	"github.com/guirongguo/ghz_demo/server"
	"google.golang.org/grpc"
	"google.golang.org/grpc/reflection"
	"log"
	"net"
	"os"
	"runtime/trace"
	"sync"
	"time"
)

func main() {
	//注意的是每次开启都要对应一个独立的文件, 重复的文件会报错, go Tracer是支持动态开启的, 所以可以灵活地控制其输出到不同的文件
	f, _ := os.Create("trace_001.out")
	defer f.Close()
	trace.Start(f)
	defer trace.Stop()

	wg := sync.WaitGroup{}
	wg.Add(3)

	go fetchResource("Task1", &wg)
	go fetchResource("Task2", &wg)
	go fetchResource("Task3", &wg)

	wg.Wait()

	fmt.Println("Finish Main...")
}

func fetchResource(name string, wg *sync.WaitGroup) {
	time.Sleep(30*time.Millisecond)
	fmt.Println(name + " Fetch Success")
	go fetchSubResource("Sub Task")
	wg.Done()
}

func fetchSubResource(name string) {
	time.Sleep(20*time.Millisecond)
	fmt.Println(name + " Fetch Success")
}

直接运行, 然后使用go tool trace -http=127.0.0.1:8080 trace_001.out, 然后进入分析页面:

image.png

• 查看Goroutines数
  

  image.png
• 查看Goroutines栈图
  

  image.png
• 查看时延分布
  

  image.png

实战