"Go test - CPU 配置文件"不会生成完整的跟踪



问题

我有一个go包,里面有一个测试套件。

当我为这个包运行测试套件时,总运行时间约为7秒:

$ go test ./mydbpackage/ -count 1
ok      mymodule/mydbpackage    7.253s

但是,当我添加-cpuprofile=cpu.out选项时,采样不会覆盖整个运行:

$ go test ./mydbpackage/ -count 1 -cpuprofile=cpu.out
ok      mymodule/mydbpackage    7.029s
$ go tool pprof -text -cum cpu.out
File: mydbpackage.test
Type: cpu
Time: Aug 6, 2020 at 9:42am (CEST)
Duration: 5.22s, Total samples = 780ms (14.95%)     # <--- depending on the runs, I get 400ms to 1s
Showing nodes accounting for 780ms, 100% of 780ms total
flat  flat%   sum%        cum   cum%
0     0%     0%      440ms 56.41%  testing.tRunner
10ms  1.28%  1.28%      220ms 28.21%  database/sql.withLock
10ms  1.28%  2.56%      180ms 23.08%  runtime.findrunnable
0     0%  2.56%      180ms 23.08%  runtime.mcall
...

查看收集的样本:

# sample from another run :
$ go tool pprof -traces cpu.out | grep "ms "  # get the first line of each sample
10ms   runtime.nanotime
10ms   fmt.(*readRune).ReadRune
30ms   syscall.Syscall
10ms   runtime.scanobject
10ms   runtime.gentraceback
...
# 98 samples collected, for a total sum of 1.12s

我看到的问题是:由于某种原因,采样探查器停止收集样本,或者在某个时刻被阻止/减慢。

上下文

go版本为1.14.6,平台为linux/amd64

$ go version
go version go1.14.6 linux/amd64

这个包包含与数据库交互的代码,并且测试是在实时postgresql服务器上运行的。

我尝试了一件事:t.Skip()在内部调用runtime.Goexit(),所以我用一个简单的return替换了对t.Skip和变体的调用;但这并没有改变结果。

问题

为什么没有收集更多的样本?是否有一些已知的模式会阻塞/减慢采样器,或者提前终止采样器?

@Volker在他的评论中引导我找到了答案:
-cpuprofile创建了一个配置文件,其中只对活跃使用CPU的goroutine进行采样。

在我的用例中:我的go代码花了很多时间等待postgresql服务器的答案。

使用go test -trace=trace.out生成跟踪,然后使用go tool trace -pprof=net trace.out > network.out提取网络阻塞配置文件,得到了更多相关信息。

作为参考,除了使用go tool trace trace.out打开完整的跟踪之外,以下是可以传递给-pprof=:的值

来自go tool trace文档:

  • net:网络阻塞配置文件
  • sync:同步阻止配置文件
  • syscall:syscall阻塞配置文件
  • sched:调度程序延迟配置文件

相关内容

  • 没有找到相关文章

最新更新