golang pprof 监控系列 go trace统计原理与使用解析

2023-05-14 17:05:11 原理 监控 解析

引言

服务监控系列文章

服务监控系列视频

关于go tool trace的使用,网上有相当多的资料,但拿我之前初学golang的经验来讲,很多资料都没有把go tool trace中的相关指标究竟是统计的哪些方法,统计了哪段区间讲解清楚。所以这篇文章不仅仅会介绍go tool trace的使用,也会对其统计的原理进行剖析。

golang版本 go1.17.12

先简单说下go tool trace 的使用场景,在分析延迟性问题的时候,go tool trace能起到很重要的作用,因为它会记录各种延迟事件并且对其进行时长分析,连关键代码位置也能找出来。

关于trace的实战案例,之前有出过一个视频(一次系统延迟分析案例),欢迎浏览

接着我们简单看下golang 里如何使用trace 功能。

go trace 使用

package main
import (
	_ "net/Http/pprof"
	"os"
	"runtime/trace"
)
func main() {
	f, _ := os.Create("trace.out")
	defer f.Close()
	trace.Start(f)
	defer trace.Stop()
  ......
}

使用trace的功能其实比较容易,用trace.Start 便可以开启trace的事件采样功能,trace.Stop 则停止采用,采样的数据会记录到trace.Start 传来的输出流参数里,这里我是将一个名为trace.out 的文件作为输出流参数传入。

采样结束后便可以通过 go tool trace trace.out命令对采样文件进行分析了。

go tool trace 命令默认会使用本地随机一个端口来启动一个http服务,页面显示如下:

接着我会分析下各个链接对应的统计信息以及背后进行统计的原理,好的,接下来,正戏开始。

统计原理介绍

平时在使用prometheus对应用服务进行监控时,我们主要还是采用埋点的方式,同样,go runtime内部也是采用这样的方式对代码运行过程中的各种事件进行埋点,最后读取 整理后的埋点数据,形成我们在网页上看的trace监控图。

// src/runtime/trace.go:517
func traceEvent(ev byte, skip int, args ...uint64) {
	mp, pid, bufp := traceAcquireBuffer()
    .....
}

每次要记录相应的事件时,都会调用traceEvent方法,ev代表的是事件枚举,skip 是看栈帧需要跳跃的层数,args 在某些事件需要传入特定参数时传入。

在traceEvent 内部同时也会获取到当前事件发生时的线程信息,协程信息,p运行队列信息,并把这些信息同事件一起记录到一个缓冲区里。

// src/runtime/trace/trace.go:120 
func Start(w io.Writer) error {
	tracing.Lock()
	defer tracing.Unlock()
	if err := runtime.StartTrace(); err != nil {
		return err
	}
	go func() {
		for {
			data := runtime.ReadTrace()
			if data == nil {
				break
			}
			w.Write(data)
		}
	}()
	atomic.StoreInt32(&tracing.enabled, 1)
	return nil
}

在我们启动trace.Start方法的时候,同时会启动一个协程不断读取缓冲区中的内容到strace.Start 的参数中。

在示例代码里,trace.Start 方法传入名为trace.out文件的输出流参数,所以在采样过程中,runtime会将采集到的事件字节流输出到trace.out文件,trace.out文件在被读取出的时候 是用了一个叫做Event的结构体来表示这些监控事件。

// Event describes one event in the trace.
type Event struct {
	Off   int       // offset in input file (for debugging and error reporting)
	Type  byte      // one of Ev*
	seq   int64     // sequence number
	Ts    int64     // timestamp in nanoseconds
	P     int       // P on which the event happened (can be one of TimerP, NetpollP, SyscallP)
	G     uint64    // G on which the event happened
	StkID uint64    // unique stack ID
	Stk   []*Frame  // stack trace (can be empty)
	Args  [3]uint64 // event-type-specific arguments
	SArgs []string  // event-type-specific string args
	// linked event (can be nil), depends on event type:
	// for GCStart: the GCStop
	// for GCSTWStart: the GCSTWDone
	// for GCSweepStart: the GCSweepDone
	// for GoCreate: first GoStart of the created goroutine
	// for GoStart/GoStartLabel: the associated GoEnd, GoBlock or other blocking event
	// for GoSched/GoPreempt: the next GoStart
	// for GoBlock and other blocking events: the unblock event
	// for GoUnblock: the associated GoStart
	// for blocking GoSysCall: the associated GoSysExit
	// for GoSysExit: the next GoStart
	// for GCMarkAssistStart: the associated GCMarkAssistDone
	// for UserTaskCreate: the UserTaskEnd
	// for UserRegion: if the start region, the corresponding UserRegion end event
	Link *Event
}

来看下Event事件里包含哪些信息: P 是运行队列,go在运行协程时,是将协程调度到P上运行的,G 是协程id,还有栈id StkID ,栈帧 Stk,以及事件发生时可以携带的一些参数Args,SArgs。 Type 是事件的枚举字段,Ts是事件发生的时间戳信息,Link 是与事件关联的其他事件,用于计算关联事件的耗时。

拿计算系统调用耗时来说,系统调用相关的事件有GoSysExit,GoSysCall 分别是系统调用退出事件和系统调用开始事件,所以GoSysExit.Ts - GoSysCall.Ts 就是系统调用的耗时。

特别提示: runtime 内部用到的监控事件枚举在src/runtime/trace.go:39 位置 ,而 在读取文件中的监控事件用到的枚举是 在src/internal/trace/parser.go:1028 ,虽然是两套,但是值是一样的。

很明显Link 字段不是在runtime 记录监控事件时设置的,而是在读取trace.out里的监控事件时,将事件信息按照协程id分组后 进行设置的。同一个协程的 GoSysExit.Ts - GoSysCall.Ts 就是该协程的系统调用耗时。

接下来我们来挨个分析下trace页面的统计信息以及背后的统计原理。

View trace是每个事件的时间线构成的监控图,在生产环境下1s都会产生大量的事件,我认为直接看这张图还是会让人眼花缭乱。 所以还是跳过它吧,从Goroutine analysis开始分析。

Goroutine analysis

go tool trace最终引用的代码位置是在go/src/cmd/trace 包下,main函数会启动一个http服务,并且注册一些处理函数,我们点击Goroutine analysis 其实就是请求到了其中一个处理函数上。 下面这段代码是注册的goroutine的处理函数点击Goroutine analysis 就会映射到 /goroutines 路由上。

// src/cmd/trace/goroutines.go:22
func init() {
	http.HandleFunc("/goroutines", httpGoroutines)
	http.HandleFunc("/goroutine", httpGoroutine)
}

让我们点击下 Goroutine analysis

进入到了一个显示代码调用位置的列表,列表中的每个代码位置都是事件EvGoStart 协程开始运行时的位置,其中N代表 在采用期间 在这个位置上有N个协程开始过运行。

你可能会好奇,是怎样确定这10个协程是由同一段代码执行的?runtime在记录协程开始执行的事件EvGoStart 时,是会把栈帧也记录下来的,而栈帧中包含函数名和程序计数器(PC)的值,在Goroutine analysis 页面 中就是协程就是按PC的值进行分组的。 以下是PC赋值的代码片段。

// src/internal/trace/goroutines.go:176
case EvGoStart, EvGoStartLabel:
			g := gs[ev.G]
			if g.PC == 0 {
				g.PC = ev.Stk[0].PC
				g.Name = ev.Stk[0].Fn
			}

我们再点击第一行链接 nfw/nfw_base/fw/routine.(*Worker).TryRun.func1 N=10 ,这里点击第一行的链接将会映射到 /goroutine 的路由上(注意路由已经不是s结尾了),由它的处理函数进行处理。点击后如图所示:

现在看到的就是针对这10个协程分别的系统调用,阻塞,调度延迟,gc这些统计信息。

接着我们从上到下挨个分析: Execution Time 是指着10个协程的执行时间占所有协程执行的比例。 接着是用于分析网络等待时间,block时间,系统调用阻塞时间 ,调度等待时间的图片,这些都是分析系统延迟,阻塞问题的利器。 这里就不再分析图了,相信网上会有很多这种资料。

然后来看下 表格里的各项指标:

Execution

是协程在采样这段时间内的执行时间。

记录的方式也很简单,在读取event事件时,是按时间线从前往后读取,每次读取到协程开始执行的时间时,会记录下协程的开始执行的时间戳(时间戳是包含在Event结构里的),读取到协程停顿事件时,则会把停顿时刻的时间戳减去开始执行的时间戳 得到 一小段的执行时间,将这小段的时间 累加到该协程的总执行时间上。

停顿则是由锁block,系统调用阻塞,网络等待,抢占调度造成的。

Network wait

顾名思义,网络等待时长, 其实也是和Execution类似的记录方式,首先记录下协程在网络等待时刻的时间戳,由于event是按时间线读取的,当读取到unblock事件时,再去看协程上一次是不是网络等待事件,如果是的话,则将当前时刻时间戳减去 网络等待时刻的时间戳,得到的这一小段时间,累加到该协程的总网络等待时长上。

Sync block,Blocking syscall,Scheduler wait

这三个时长 计算方式和前面两张也是类似的,不过注意下与之相关联的事件的触发条件是不同的。

Sync block 时长是由于 锁 sync.mutex ,通道channel,wait group,select case语句产生的阻塞都会记录到这里。 下面是相关代码片段。

// src/internal/trace/goroutines.go:192
case EvGoBlockSend, EvGoBlockRecv, EvGoBlockSelect,
			EvGoBlockSync, EvGoBlockCond:
			g := gs[ev.G]
			g.ExecTime += ev.Ts - g.lastStartTime
			g.lastStartTime = 0
			g.blockSyncTime = ev.Ts

Blocking syscall 就是系统调用造成的阻塞了。

Scheduler wait 是协程从可执行状态到执行状态的时间段,注意协程是可执行状态时 是会放到p 运行队列等待被调度的,只有被调度后,才会真正开始执行代码。 这里涉及到golang gpm模型的理解,这里就不再展开了。

后面两栏就是GC 占用total时间的一个百分比了,golang 的gc相关的知识也不继续展开了。

各种profile 图

还记得最开始分析trace.out生成的网页时,Goroutine analysis 下面是什么吗?是各种分析延迟相关的profile 图,数据的来源和我们讲Goroutine analysis 时分析单个Goroutine 的等待时间的指标是一样的,不过这里是针对所有goroutine而言。

Network blocking profile (⬇)
Synchronization blocking profile (⬇)
Syscall blocking profile (⬇)
Scheduler latency profile (⬇)

关于golang 的这个trace工具,还允许用户可以自定义监控事件 ,生成的trace网页里,User-defined tasks,User-defined regions 就是记录用户自定义的一些监控事件,这部分的应用等到以后再讲了。

Minimum mutator utilization 是一个看gc 对程序影响情况的曲线图,这个等以后有机会讲gc时再详细谈谈了。

以上就是golang pprof 监控系列 go trace统计原理与使用解析的详细内容,更多关于golang pprof监控go trace统计的资料请关注其它相关文章!

相关文章