这篇文章主要介绍“golang pprof监控系列go trace统计原理与使用方法是什么”,在日常操作中,相信很多人在golang pprof监控系列go trace统计原理与使用方法是什么问题上存在疑惑,小编查阅了各式资料,整理出简单好用的操作方法,希望对大家解答”golang pprof监控系列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开始分析。
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时间,系统调用阻塞时间 ,调度等待时间的图片,这些都是分析系统延迟,阻塞问题的利器。 这里就不再分析图了,相信网上会有很多这种资料。
然后来看下 表格里的各项指标:
是协程在采样这段时间内的执行时间。
记录的方式也很简单,在读取event事件时,是按时间线从前往后读取,每次读取到协程开始执行的时间时,会记录下协程的开始执行的时间戳(时间戳是包含在Event结构里的),读取到协程停顿事件时,则会把停顿时刻的时间戳减去开始执行的时间戳 得到 一小段的执行时间,将这小段的时间 累加到该协程的总执行时间上。
停顿则是由锁block,系统调用阻塞,网络等待,抢占调度造成的。
顾名思义,网络等待时长, 其实也是和Execution类似的记录方式,首先记录下协程在网络等待时刻的时间戳,由于event是按时间线读取的,当读取到unblock事件时,再去看协程上一次是不是网络等待事件,如果是的话,则将当前时刻时间戳减去 网络等待时刻的时间戳,得到的这一小段时间,累加到该协程的总网络等待时长上。
这三个时长 计算方式和前面两张也是类似的,不过注意下与之相关联的事件的触发条件是不同的。
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相关的知识也不继续展开了。
还记得最开始分析trace.out生成的网页时,Goroutine analysis 下面是什么吗?是各种分析延迟相关的profile 图,数据的来源和我们讲Goroutine analysis 时分析单个Goroutine 的等待时间的指标是一样的,不过这里是针对所有goroutine而言。
Network blocking profile (⬇) Synchronization blocking profile (⬇) Syscall blocking profile (⬇) Scheduler latency profile (⬇)
到此,关于“golang pprof监控系列go trace统计原理与使用方法是什么”的学习就结束了,希望能够解决大家的疑惑。理论与实践的搭配能更好的帮助大家学习,快去试试吧!若想继续学习更多相关知识,请继续关注亿速云网站,小编会继续努力为大家带来更多实用的文章!
免责声明:本站发布的内容(图片、视频和文字)以原创、转载和分享为主,文章观点不代表本网站立场,如果涉及侵权请联系站长邮箱:is@yisu.com进行举报,并提供相关证据,一经查实,将立刻删除涉嫌侵权内容。