如何优化golang程序中运行时间最长的runtime.osyield和runtime.usleep？

Question

我一直在优化代码以分析社交网络数据（在https://blog.golang.org/profiling-go-programs的帮助下），并已成功重构了大量缓慢的代码。

所有数据首先从数据库加载到内存中，然后从那里进行数据分析，似乎 CPU 受限（最大内存消耗 <10MB，CPU1 @ 100%）

但现在，我的程序大部分时间似乎用在 runtime.osyield 和 runtime.usleep 上。有什么方法可以防止这种情况发生吗？

我已经设置 GOMAXPROCS=1，并且该代码不会生成任何 goroutine（除了 golang 库可能调用的 goroutine 之外）。

这是 pprof 的 top10 输出：

(pprof) top10
62550ms of 72360ms total (86.44%)
Dropped 208 nodes (cum <= 361.80ms)
Showing top 10 nodes out of 77 (cum >= 1040ms)
      flat  flat%   sum%        cum   cum%
   20760ms 28.69% 28.69%    20850ms 28.81%  runtime.osyield
   14070ms 19.44% 48.13%    14080ms 19.46%  runtime.usleep
   11740ms 16.22% 64.36%    23100ms 31.92%  _/C_/code/sc_proto/cloudgraph.(*Graph).LeafProb
    6170ms  8.53% 72.89%     6170ms  8.53%  runtime.memmove
    4740ms  6.55% 79.44%    10660ms 14.73%  runtime.typedslicecopy
    2040ms  2.82% 82.26%     2040ms  2.82%  _/C_/code/sc_proto.mAvg
     890ms  1.23% 83.49%     1590ms  2.20%  runtime.scanobject
     770ms  1.06% 84.55%     1420ms  1.96%  runtime.mallocgc
     760ms  1.05% 85.60%      760ms  1.05%  runtime.heapBitsForObject
     610ms  0.84% 86.44%     1040ms  1.44%  _/C_/code/sc_proto/cloudgraph.(*Node).DeepestChildren
(pprof)

_ /C_/code/sc_proto/* 函数是我的代码。

而来自 web 的输出：

（更好的 SVG 图片版本在此处：https://goo.gl/Tyc6X4）

- Aaron

---

你的图表难以辨认。你没有告诉我们你的程序在做什么。如何创建一个最小、完整和可验证的示例。 - peterSO

@JimB 不使用cgo；全部都是纯Go。 - Aaron

我猜测你的程序被阻塞了，这就是为什么它经常让出CPU的原因。你可以运行一个阻塞分析，但如果没有实际的代码和数据，我们在这里也无能为力。 - JimB

@JimB 肯定被阻塞了（通过调用 yield 和 sleep 很清楚），但很难与主 CPU 的 100% 利用率相一致。看起来是有多个 goroutine 在运行？ - Aaron

@Aaron：总是有多个goroutine在运行（以及多个操作系统线程）。GOMAXPROCS仅控制有多少操作系统线程可用于运行用户级别的代码。 - JimB

Answer 1

我自己找到了答案，所以在这里发布出来，供其他遇到类似问题的人参考。特别感谢@JimB给我指明了正确的方向。

从图表中可以看出，导致osyield和usleep的路径是垃圾收集例程。这个程序使用了一个生成了很多指针的链表，这为垃圾收集器带来了很多工作，有时会在清理我的“垃圾”时阻塞我的代码执行。

最终，解决这个问题的方法来自于https://software.intel.com/en-us/blogs/2014/05/10/debugging-performance-issues-in-go-programs（顺便说一句，这是一个很棒的资源）。我遵循了那里的内存分析器的说明；并且按照建议用切片替换了指针集合，清除了我的垃圾收集问题，现在我的代码运行速度更快了！

- Aaron

---

哪个SQL驱动程序？（顺便说一句，我也发现累积输出很有帮助，因为它显示了函数调用的时间更像是调用堆栈） - JimB

驱动程序是Go-SQL-driver，位于：https://github.com/go-sql-driver/mysql我得出的结论是我的数据库驱动程序是导致线程让步的原因，因为在http://localhost:6060/debug/pprof/goroutine?debug=1的输出中，我看到了以下内容：1 @ 0x43079c 0x43086b 0x40487d 0x4043bb 0x5451ec 0x45f0e1 # 0x5451ec database/sql.(*DB).connectionOpener+0x4c C:/Go/src/database/sql/sql.go:727以及我的goroutine（下一个评论） - Aaron

`1 @ 0x441d10 0x53447a 0x48ba79 0x48d7f7 0x48cfe5 0x49b7da 0x48dc02 0x49a8db 0x480e9f 0x45f0e1

0x53447a /C/code/sc_proto/cloudgraph.(*Node).AddChild+0x8a C:/code/sc_proto/cloudgraph/cloudgraph.go:92

0x49b7da /C/code/sc_proto.main.func3+0x7a C:/code/sc_proto/main.go:887

0x48dc02 /C/code/sc_proto.main+0x1d2 C:/code/sc_proto/main.go:908

0x49a8db /C/code/sc_proto.Test_main+0x1b C:/code/sc_proto/main_test.go:1002

0x480e9f testing.tRunner+0x9f C:/Go/src/testing/testing.go:473`

- Aaron

我不确定你从中推断出了什么，但是goroutine的存在并不意味着它正在消耗任何CPU。 - JimB

看起来那篇博客的链接已经失效了。 - user5359531

看起来这篇博客文章可以在这里查看：https://web.archive.org/web/20140801000350/https://software.intel.com/en-us/blogs/2014/05/10/debugging-performance-issues-in-go-programs - user5359531