本文转载自微信公众号「脑子进煎鱼了」,作者陈煎鱼。转载本文请联系脑子进煎鱼了公众号。
创新互联建站是一家专业提供营山企业网站建设,专注与网站制作、成都网站建设、H5场景定制、小程序制作等业务。10年已为营山众多企业、政府机构等服务。创新互联专业网络公司优惠进行中。
大家好,我是煎鱼。
前段时间分享了《Go 程序崩了?煎鱼教你用 PProf 工具来救火!》,但有时候单单使用 pprof 还不一定足够完整观查并解决问题,因为在真实的程序中还包含许多的隐藏动作,例如:
这些东西用 pprof 是很难分析出来的,但如果你又想知道上述的答案的话,你可以用本章节的主角 go tool trace 来打开新世界的大门。
一起愉快地开始吸鱼之路。
- import (
- "os"
- "runtime/trace"
- )
- func main() {
- trace.Start(os.Stderr)
- defer trace.Stop()
- ch := make(chan string)
- go func() {
- ch <- "Go语言编程之旅"
- }()
- <-ch
- }
生成跟踪文件:
- $ go run main.go 2> trace.out
启动可视化界面:
- $ go tool trace trace.out
- 2019/06/22 16:14:52 Parsing trace...
- 2019/06/22 16:14:52 Splitting trace...
- 2019/06/22 16:14:52 Opening browser. Trace viewer is listening on http://127.0.0.1:57321
查看可视化界面:
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”,我们能通过 Graph 看到整体的调用开销情况,如下:
演示程序比较简单,因此这里就两块,一个是 trace 本身,另外一个是 channel 的收发。
第二步看 “Goroutine analysis”,我们能通过这个功能看到整个运行过程中,每个函数块有多少个有 Goroutine 在跑。
观察每个的 Goroutine 的运行开销都花费在哪个阶段。如下:
通过上图我们可以看到共有 3 个 goroutine,分别是:
- runtime.main。
- runtime/trace.Start.func1。
- main.main.func1。
它们都做了些什么事呢,我们可以通过点击具体细项去观察。如下:
同时也可以看到当前 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 |
在对当前程序的 Goroutine 运行分布有了初步了解后,我们再通过 “查看跟踪” 看看之间的关联性,如下:
这个跟踪图粗略一看,相信有的小伙伴会比较懵逼,我们可以依据注解一块块查看,如下:
点击具体的 Goroutine 行为后可以看到其相关联的详细信息,这块很简单,大家实际操作一下就懂了。文字解释如下:
我们可以通过点击 View Options-Flow events、Following events 等方式,查看我们应用运行中的事件流情况。如下:
通过分析图上的事件流,我们可得知:
这程序从 G1 runtime.main 开始运行。
在运行时创建了 2 个 Goroutine:
同时我们可以通过其 Goroutine Name 去了解它的调用类型。如下:
runtime/trace.Start.func1 就是程序中在 main.main 调用了 runtime/trace.Start 方法。
紧接着该方法又利用协程创建了一个闭包 func1 去进行调用。
在这里我们结合开头的代码去看的话,很明显就是 ch 的输入输出的过程了。
凌晨三点,突然生产环境突然出现了问题,机智的你早已埋好 _ "net/http/pprof" 这个神奇的工具。
被告警电话叫醒的你,迷迷糊糊地通过特定的方式执行了如下命令:
- $ curl http://127.0.0.1:6060/debug/pprof/trace\?seconds\=20 > trace.out
- $ go tool trace trace.out
你很快的看到了熟悉的 List 界面,然后不信邪点开了 View trace 界面,如下:
完全看懵的你,稳住,对着合适的区域执行快捷键 W 不断地放大时间线,如下:
经过初步排查,你发现上述绝大部分的 G 竟然都和 google.golang.org/grpc.(*Server).Serve.func 有关,关联的一大串也是 Serve 所触发的相关动作。
这时候有经验的你心里已经有了初步结论,你可以继续追踪 View trace 深入进去。
不过建议先鸟瞰全貌,因此我们再往下看 “Network blocking profile” 和 “Syscall blocking profile” 所提供的信息。
通过对以上三项的跟踪分析,加上这个泄露,这个阻塞的耗时,这个涉及的内部方法名,很明显就是哪位又忘记关闭客户端连接了。
这时候我们就可以接下进行下一步的排查和修改了。
通过本文我们习得了 go tool trace 的武林秘籍,它能够跟踪捕获各种执行中的事件,例如:
希望你能够用好 Go 的两大杀器 pprof + trace 组合,此乃排查好搭档,谁用谁清楚,即使他并不是绝对的万能。
名称栏目:Go 工程师必学:Go 大杀器之跟踪剖析 Trace
地址分享:http://www.stwzsj.com/qtweb/news1/14601.html
网站建设、网络推广公司-创新互联,是专注品牌与效果的网站制作,网络营销seo公司;服务项目有等
声明:本网站发布的内容(图片、视频和文字)以用户投稿、用户转载内容为主,如果涉及侵权请尽快告知,我们将会在第一时间删除。文章观点不代表本网站立场,如需处理请联系客服。电话:028-86922220;邮箱:631063699@qq.com。内容未经允许不得转载,或转载时需注明来源: 创新互联