103

Go运行时bug调试过程解析

 6 years ago
source link: http://www.iteye.com/news/32819?amp%3Butm_medium=referral
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

Go运行时bug调试过程解析 - 编程语言 - ITeye资讯

声明:ITeye资讯文章的版权属于ITeye网站所有,严禁任何网站转载本文,否则必将追究法律责任!

原文:Debugging an evil Go runtime bug
作者:Hector Martin
翻译:雁惊寒

摘要:本文讲述了作者通过对硬件、内核进行分析来调试程序bug的整个过程。以下是译文。

前言

我是PrometheusGrafana的超级粉丝。作为一名前谷歌SRE(Site Reliability Engineer, 网站可靠性工程师),我学会了如何选择优秀的监控应用程序。这个组合在过去的一年中一直是我战无不胜的法宝。我使用它们监控我自己的个人服务器(包括黑盒和白盒监控)、为我的客户提供专业的技术支持,以及实现其他很多的功能。 使用Prometheus编写自定义导出程序来监视数据非常地简单,而且你可以很方便地在其他地方找到一个适合于自己的可用的导出程序。例如,我们使用sql_exporter为Encounter事件制作了一个非常漂亮的仪表盘。

87d48104-0761-3b55-b097-f72f080b38dd.png
Euskal Encounter的事件仪表盘

由于把node_exporter部署到任何一台机器上都非常简单,并且它能运行一个Prometheus实例来为机器做基本的系统级监控(包括CPU、内存、网络、磁盘、文件系统的使用情况等),那么我想,为什么不监视一下我的笔记本电脑呢?我有一台Clevo“游戏”笔记本电脑,它是我主要的工作电脑,大部分时间都是假装在家里做台式机,有时也会和我一起参加像混沌通信大会(
Chaos Communication Congress)这样的大型活动。由于我已经在它和一台运行Prometheus的服务器之间建立了VPN链接,所以,我可以通过执行emerge prometheus-node_exporter来启动服务,指向Prometheus实例,并自动为其配置警报。这意味着每当我打开太多Chrome选项卡并耗光32GB内存的时候,我的手机就会收到报警。完美!

问题浮现

不过,在设置完的一个小时之后,我的手机确实出现了一个提示:新添加的目标无法访问。我可以SSH到笔记本电脑,说明电脑运行正常,但node_exporter已经崩溃了。

  1. fatal error: unexpected signal during runtime execution  
  2. [signal SIGSEGV: segmentation violation code=0x1 addr=0xc41ffc7fff pc=0x41439e]  
  3. goroutine 2395 [running]:  
  4. runtime.throw(0xae6fb8, 0x2a)  
  5.         /usr/lib64/go/src/runtime/panic.go:605 +0x95 fp=0xc4203e8be8 sp=0xc4203e8bc8 pc=0x42c815  
  6. runtime.sigpanic()  
  7.         /usr/lib64/go/src/runtime/signal_unix.go:351 +0x2b8 fp=0xc4203e8c38 sp=0xc4203e8be8 pc=0x443318  
  8. runtime.heapBitsSetType(0xc4204b6fc0, 0x30, 0x30, 0xc420304058)  
  9.         /usr/lib64/go/src/runtime/mbitmap.go:1224 +0x26e fp=0xc4203e8c90 sp=0xc4203e8c38 pc=0x41439e  
  10. runtime.mallocgc(0x30, 0xc420304058, 0x1, 0x1)  
  11.         /usr/lib64/go/src/runtime/malloc.go:741 +0x546 fp=0xc4203e8d38 sp=0xc4203e8c90 pc=0x411876  
  12. runtime.newobject(0xa717e0, 0xc42032f430)  
  13.         /usr/lib64/go/src/runtime/malloc.go:840 +0x38 fp=0xc4203e8d68 sp=0xc4203e8d38 pc=0x411d68  
  14. github.com/prometheus/node_exporter/vendor/github.com/prometheus/client_golang/prometheus.NewConstMetric(0xc42018e460, 0x2, 0x3ff0000000000000, 0xc42032f430, 0x1, 0x1, 0x10, 0x9f9dc0, 0x8a0601, 0xc42032f430)  
  15.         /var/tmp/portage/net-analyzer/prometheus-node_exporter-0.15.0/work/prometheus-node_exporter-0.15.0/src/github.com/prometheus/node_exporter/vendor/github.com/prometheus/client_golang/prometheus/value.go:165 +0xd0 fp=0xc4203e8dd0 sp=0xc4203e8d68 pc=0x77a980  
fatal error: unexpected signal during runtime execution
[signal SIGSEGV: segmentation violation code=0x1 addr=0xc41ffc7fff pc=0x41439e]

goroutine 2395 [running]:
runtime.throw(0xae6fb8, 0x2a)
        /usr/lib64/go/src/runtime/panic.go:605 +0x95 fp=0xc4203e8be8 sp=0xc4203e8bc8 pc=0x42c815
runtime.sigpanic()
        /usr/lib64/go/src/runtime/signal_unix.go:351 +0x2b8 fp=0xc4203e8c38 sp=0xc4203e8be8 pc=0x443318
runtime.heapBitsSetType(0xc4204b6fc0, 0x30, 0x30, 0xc420304058)
        /usr/lib64/go/src/runtime/mbitmap.go:1224 +0x26e fp=0xc4203e8c90 sp=0xc4203e8c38 pc=0x41439e
runtime.mallocgc(0x30, 0xc420304058, 0x1, 0x1)
        /usr/lib64/go/src/runtime/malloc.go:741 +0x546 fp=0xc4203e8d38 sp=0xc4203e8c90 pc=0x411876
runtime.newobject(0xa717e0, 0xc42032f430)
        /usr/lib64/go/src/runtime/malloc.go:840 +0x38 fp=0xc4203e8d68 sp=0xc4203e8d38 pc=0x411d68
github.com/prometheus/node_exporter/vendor/github.com/prometheus/client_golang/prometheus.NewConstMetric(0xc42018e460, 0x2, 0x3ff0000000000000, 0xc42032f430, 0x1, 0x1, 0x10, 0x9f9dc0, 0x8a0601, 0xc42032f430)
        /var/tmp/portage/net-analyzer/prometheus-node_exporter-0.15.0/work/prometheus-node_exporter-0.15.0/src/github.com/prometheus/node_exporter/vendor/github.com/prometheus/client_golang/prometheus/value.go:165 +0xd0 fp=0xc4203e8dd0 sp=0xc4203e8d68 pc=0x77a980


像其他的Prometheus组件一样,node_exporter是用Go编写的。 Go是一种相对安全的语言,尽管有的时候你可能会搬起石头砸自己的脚,而且它不像Rust那样具有强有力的安全保证,但是,要在Go中产生段错误也并不是那么容易的。 况且,node_exporter是一个相对来说比较简单的Go应用程序,只单纯的依赖Go。 因此,这是一个非常有趣的崩溃,特别是崩溃在mallocgc里面。一般情况下,这里永远都不会崩溃。

重启几次之后,事情变得更有趣了:

  1. 2017/11/07 06:32:49 http: panic serving 172.20.0.1:38504: runtime error: growslice: cap out of range  
  2. goroutine 41 [running]:  
  3. net/http.(*conn).serve.func1(0xc4201cdd60)  
  4.         /usr/lib64/go/src/net/http/server.go:1697 +0xd0  
  5. panic(0xa24f20, 0xb41190)  
  6.         /usr/lib64/go/src/runtime/panic.go:491 +0x283  
  7. fmt.(*buffer).WriteString(...)  
  8.         /usr/lib64/go/src/fmt/print.go:82  
  9. fmt.(*fmt).padString(0xc42053a040, 0xc4204e6800, 0xc4204e6850)  
  10.         /usr/lib64/go/src/fmt/format.go:110 +0x110  
  11. fmt.(*fmt).fmt_s(0xc42053a040, 0xc4204e6800, 0xc4204e6850)  
  12.         /usr/lib64/go/src/fmt/format.go:328 +0x61  
  13. fmt.(*pp).fmtString(0xc42053a000, 0xc4204e6800, 0xc4204e6850, 0xc400000073)  
  14.         /usr/lib64/go/src/fmt/print.go:433 +0x197  
  15. fmt.(*pp).printArg(0xc42053a000, 0x9f4700, 0xc42041c290, 0x73)  
  16.         /usr/lib64/go/src/fmt/print.go:664 +0x7b5  
  17. fmt.(*pp).doPrintf(0xc42053a000, 0xae7c2d, 0x2c, 0xc420475670, 0x2, 0x2)  
  18.         /usr/lib64/go/src/fmt/print.go:996 +0x15a  
  19. fmt.Sprintf(0xae7c2d, 0x2c, 0xc420475670, 0x2, 0x2, 0x10, 0x9f4700)  
  20.         /usr/lib64/go/src/fmt/print.go:196 +0x66  
  21. fmt.Errorf(0xae7c2d, 0x2c, 0xc420475670, 0x2, 0x2, 0xc420410301, 0xc420410300)  
  22.         /usr/lib64/go/src/fmt/print.go:205 +0x5a  
2017/11/07 06:32:49 http: panic serving 172.20.0.1:38504: runtime error: growslice: cap out of range
goroutine 41 [running]:
net/http.(*conn).serve.func1(0xc4201cdd60)
        /usr/lib64/go/src/net/http/server.go:1697 +0xd0
panic(0xa24f20, 0xb41190)
        /usr/lib64/go/src/runtime/panic.go:491 +0x283
fmt.(*buffer).WriteString(...)
        /usr/lib64/go/src/fmt/print.go:82
fmt.(*fmt).padString(0xc42053a040, 0xc4204e6800, 0xc4204e6850)
        /usr/lib64/go/src/fmt/format.go:110 +0x110
fmt.(*fmt).fmt_s(0xc42053a040, 0xc4204e6800, 0xc4204e6850)
        /usr/lib64/go/src/fmt/format.go:328 +0x61
fmt.(*pp).fmtString(0xc42053a000, 0xc4204e6800, 0xc4204e6850, 0xc400000073)
        /usr/lib64/go/src/fmt/print.go:433 +0x197
fmt.(*pp).printArg(0xc42053a000, 0x9f4700, 0xc42041c290, 0x73)
        /usr/lib64/go/src/fmt/print.go:664 +0x7b5
fmt.(*pp).doPrintf(0xc42053a000, 0xae7c2d, 0x2c, 0xc420475670, 0x2, 0x2)
        /usr/lib64/go/src/fmt/print.go:996 +0x15a
fmt.Sprintf(0xae7c2d, 0x2c, 0xc420475670, 0x2, 0x2, 0x10, 0x9f4700)
        /usr/lib64/go/src/fmt/print.go:196 +0x66
fmt.Errorf(0xae7c2d, 0x2c, 0xc420475670, 0x2, 0x2, 0xc420410301, 0xc420410300)
        /usr/lib64/go/src/fmt/print.go:205 +0x5a


太有趣了。 这次Sprintf出现崩溃了。 为什么?

  1. runtime: pointer 0xc4203e2fb0 to unallocated span idx=0x1f1 span.base()=0xc4203dc000 span.limit=0xc4203e6000 span.state=3  
  2. runtime: found in object at *(0xc420382a80+0x80)  
  3. object=0xc420382a80 k=0x62101c1 s.base()=0xc420382000 s.limit=0xc420383f80 s.spanclass=42 s.elemsize=384 s.state=_MSpanInUse  
  4.  <snip>  
  5. fatal error: found bad pointer in Go heap (incorrect use of unsafe or cgo?)  
  6. runtime stack:  
  7. runtime.throw(0xaee4fe, 0x3e)  
  8.         /usr/lib64/go/src/runtime/panic.go:605 +0x95 fp=0x7f0f19ffab90 sp=0x7f0f19ffab70 pc=0x42c815  
  9. runtime.heapBitsForObject(0xc4203e2fb0, 0xc420382a80, 0x80, 0xc41ffd8a33, 0xc400000000, 0x7f0f400ac560, 0xc420031260, 0x11)  
  10.         /usr/lib64/go/src/runtime/mbitmap.go:425 +0x489 fp=0x7f0f19ffabe8 sp=0x7f0f19ffab90 pc=0x4137c9  
  11. runtime.scanobject(0xc420382a80, 0xc420031260)  
  12.         /usr/lib64/go/src/runtime/mgcmark.go:1187 +0x25d fp=0x7f0f19ffac90 sp=0x7f0f19ffabe8 pc=0x41ebed  
  13. runtime.gcDrain(0xc420031260, 0x5)  
  14.         /usr/lib64/go/src/runtime/mgcmark.go:943 +0x1ea fp=0x7f0f19fface0 sp=0x7f0f19ffac90 pc=0x41e42a  
  15. runtime.gcBgMarkWorker.func2()  
  16.         /usr/lib64/go/src/runtime/mgc.go:1773 +0x80 fp=0x7f0f19ffad20 sp=0x7f0f19fface0 pc=0x4580b0  
  17. runtime.systemstack(0xc420436ab8)  
  18.         /usr/lib64/go/src/runtime/asm_amd64.s:344 +0x79 fp=0x7f0f19ffad28 sp=0x7f0f19ffad20 pc=0x45a469  
  19. runtime.mstart()  
  20.         /usr/lib64/go/src/runtime/proc.go:1125 fp=0x7f0f19ffad30 sp=0x7f0f19ffad28 pc=0x430fe0  
runtime: pointer 0xc4203e2fb0 to unallocated span idx=0x1f1 span.base()=0xc4203dc000 span.limit=0xc4203e6000 span.state=3
runtime: found in object at *(0xc420382a80+0x80)
object=0xc420382a80 k=0x62101c1 s.base()=0xc420382000 s.limit=0xc420383f80 s.spanclass=42 s.elemsize=384 s.state=_MSpanInUse
 <snip>
fatal error: found bad pointer in Go heap (incorrect use of unsafe or cgo?)

runtime stack:
runtime.throw(0xaee4fe, 0x3e)
        /usr/lib64/go/src/runtime/panic.go:605 +0x95 fp=0x7f0f19ffab90 sp=0x7f0f19ffab70 pc=0x42c815
runtime.heapBitsForObject(0xc4203e2fb0, 0xc420382a80, 0x80, 0xc41ffd8a33, 0xc400000000, 0x7f0f400ac560, 0xc420031260, 0x11)
        /usr/lib64/go/src/runtime/mbitmap.go:425 +0x489 fp=0x7f0f19ffabe8 sp=0x7f0f19ffab90 pc=0x4137c9
runtime.scanobject(0xc420382a80, 0xc420031260)
        /usr/lib64/go/src/runtime/mgcmark.go:1187 +0x25d fp=0x7f0f19ffac90 sp=0x7f0f19ffabe8 pc=0x41ebed
runtime.gcDrain(0xc420031260, 0x5)
        /usr/lib64/go/src/runtime/mgcmark.go:943 +0x1ea fp=0x7f0f19fface0 sp=0x7f0f19ffac90 pc=0x41e42a
runtime.gcBgMarkWorker.func2()
        /usr/lib64/go/src/runtime/mgc.go:1773 +0x80 fp=0x7f0f19ffad20 sp=0x7f0f19fface0 pc=0x4580b0
runtime.systemstack(0xc420436ab8)
        /usr/lib64/go/src/runtime/asm_amd64.s:344 +0x79 fp=0x7f0f19ffad28 sp=0x7f0f19ffad20 pc=0x45a469
runtime.mstart()
        /usr/lib64/go/src/runtime/proc.go:1125 fp=0x7f0f19ffad30 sp=0x7f0f19ffad28 pc=0x430fe0


现在,垃圾收集者偶然间又发现了一个问题,是另一个崩溃。

在这一点上,很自然地就能得到两个结论:要么是硬件有严重的问题,要么在在二进制文件中存在一个严重的内存破坏缺陷。 我最初认为第一种情况不太可能,因为这台机器上运行的程序非常杂,没有出现任何不稳定的与硬件有关的迹象。 由于像node_exporter这样的Go二进制文件是静态链接的,不依赖于任何其他库,所以我可以下载正式版的二进制文件来试一下。 然而,当我这样做的时候,程序还是崩溃了。

  1. unexpected fault address 0x0  
  2. unexpected fault address 0x0  
  3. fatal error: fault  
  4. [signal SIGSEGV: segmentation violation code=0x80 addr=0x0 pc=0x76b998]  
  5. goroutine 13 [running]:  
  6. runtime.throw(0xabfb11, 0x5)  
  7.         /usr/local/go/src/runtime/panic.go:605 +0x95 fp=0xc420060c40 sp=0xc420060c20 pc=0x42c725  
  8. runtime.sigpanic()  
  9.         /usr/local/go/src/runtime/signal_unix.go:374 +0x227 fp=0xc420060c90 sp=0xc420060c40 pc=0x443197  
  10. github.com/prometheus/node_exporter/vendor/github.com/prometheus/client_model/go.(*LabelPair).GetName(...)  
  11.         /go/src/github.com/prometheus/node_exporter/vendor/github.com/prometheus/client_model/go/metrics.pb.go:85  
  12. github.com/prometheus/node_exporter/vendor/github.com/prometheus/client_golang/prometheus.(*Desc).String(0xc4203ae010, 0xaea9d0, 0xc42045c000)  
  13.         /go/src/github.com/prometheus/node_exporter/vendor/github.com/prometheus/client_golang/prometheus/desc.go:179 +0xc8 fp=0xc420060dc8 sp=0xc420060c90 pc=0x76b998  
unexpected fault address 0x0
unexpected fault address 0x0
fatal error: fault
[signal SIGSEGV: segmentation violation code=0x80 addr=0x0 pc=0x76b998]

goroutine 13 [running]:
runtime.throw(0xabfb11, 0x5)
        /usr/local/go/src/runtime/panic.go:605 +0x95 fp=0xc420060c40 sp=0xc420060c20 pc=0x42c725
runtime.sigpanic()
        /usr/local/go/src/runtime/signal_unix.go:374 +0x227 fp=0xc420060c90 sp=0xc420060c40 pc=0x443197
github.com/prometheus/node_exporter/vendor/github.com/prometheus/client_model/go.(*LabelPair).GetName(...)
        /go/src/github.com/prometheus/node_exporter/vendor/github.com/prometheus/client_model/go/metrics.pb.go:85
github.com/prometheus/node_exporter/vendor/github.com/prometheus/client_golang/prometheus.(*Desc).String(0xc4203ae010, 0xaea9d0, 0xc42045c000)
        /go/src/github.com/prometheus/node_exporter/vendor/github.com/prometheus/client_golang/prometheus/desc.go:179 +0xc8 fp=0xc420060dc8 sp=0xc420060c90 pc=0x76b998


又是一次完全不同的崩溃。这说明node_exporter的上游或者它的一个依赖项确实存在问题,所以,我在GitHub上提交了一个issue。也许开发者以前见过这个,如果他们有什么想法的话,那么引起他们的注意是非常值得的。

走了一趟并不顺畅的弯路

毫无疑问,对于上游问题,首先能想到的是这是一个硬件问题。毕竟我只是在一台特定的机器上碰到这个问题。其他所有的机器都能很顺利地运行node_exporter。虽然在这台主机上没有其他硬件连接不稳定的证据,但是我也无法解释这台机器存在能导致node_exporter崩溃的特殊性。Memtest86+的运行永远不会破坏其他程序,所以我安装了一个。

然后,发生了这个:

26bf3280-6c86-3060-80a0-27c36a00c421.png
这是我用客户的电脑所得到的

哎呀!RAM坏了。更具体点说是有一位(bit)的坏内存。在测试程序完整地运行了一遍之后,最终得到的就只是那一个坏的位,另外在测试7中存在一些误报(在附近移动块的时候出来了一个错误)。

进一步的测试表明,SMP模式下的Memtest86+测试5可以快速检测到错误,但通常不会在第一遍检测的时候发现。错误总是出现在相同的地址和相同的位上。这说明这个问题出现在一个微弱或泄漏的RAM单元上,特别是随温度会变坏的那种。这非常符合逻辑:温度的升高会增加RAM单元的泄漏,并且很有可能会引起位翻转。

从这个角度来看,这是274,877,906,944个位中的一个坏点。这实际上是一个非常不错的的错误率了!硬盘和闪存的错误率要高得多,只是这些设备在出厂时会标出坏块,在用户不知情的情况下透明地换出,并且可以将新发现的弱块透明地标记为坏块,并将其重新定位到备用区。内存并不这么奢侈,所以一个坏的位永远都是坏的。

唉,这不可能成为node_exporter崩溃的原因。那个应用程序使用的RAM很少,所以它碰到坏位的机会是非常低的。这类问题一般表现得并不会很明显,也许会导致某些图形中的像素错误、在某些文本中出现单个字母的翻转、也可能指令被破坏导致无法运行,或者当某些非常重要的数据确实落在了坏位上会出现崩溃。尽管如此,它确实会导致长期的可靠性问题,这就是服务器和其他可靠设备必须使用ECC RAM才能纠正这种错误的原因。

我没有在这台笔记本电脑上配置豪华的ECC RAM。但是我拥有将内存坏块标记为坏的能力,并告诉操作系统不要使用它。GRUB 2有一个鲜为人知的功能,它允许你改变传递给启动内核的内存映射。仅仅为了一个坏块而购买新的RAM是不值得的,所以这是一个不错的选择。

不过,还有一件事情是我可以做的。由于情况会随着温度的升高而变差,那么如果我加热RAM会发生什么呢?

595dff2f-c4a4-3fe9-a708-7d9dc2558413.jpg
memtest86+
593e151d-3531-3bfe-823c-3be0c5dc6572.jpg
惬意的100°C

我把热风枪设置到一个较低的温度(130°C),并对两个模块进行加热(其他两个模块在后盖下,因为我的笔记本电脑总共有四个SODIMM插槽)。我发现另外还有三个弱点只能在高温下才能检测到,它们分布在三个内存条上。

我还发现,即使我交换了模块的位置,发生错误的位置仍然保持大体上的一致:地址的最高位保持不变。这是因为RAM是交错的:数据遍布在四个内存条上,而不是在每个内存条上连续分配可用地址空间的四分之一。因此,我可以屏蔽一个足够大的RAM区域,以覆盖每个错误位所有可能的地址。我发现,屏蔽连续的128KB区域应该足以覆盖每个给定坏点的所有可能的地址排列,但是,为了更好的进行测量,我将它四舍五入到1MB。我用了三个1MB对齐的块来进行掩盖(其中一个块掩盖了两个坏点,我总共要掩盖四个坏点):

  • 0x36a700000 – 0x36a7fffff
  • 0x460e00000 – 0x460efffff
  • 0x4ea000000 – 0x4ea0fffff

这可以使用GRUB的地址/掩码语法来指定,/etc/default/grub如下所示:

  1. GRUB_BADRAM="0x36a700000,0xfffffffffff00000,0x460e00000,0xfffffffffff00000,0x4ea000000,0xfffffffffff00000"  
GRUB_BADRAM="0x36a700000,0xfffffffffff00000,0x460e00000,0xfffffffffff00000,0x4ea000000,0xfffffffffff00000"


不用说,node_exporter还是崩溃了,但我知道了这不并是真正的问题所在。

深度挖掘

这种错误很烦人,它显然是因为代码运行的某块内存被破坏而引起的。这种错误很难调试,因为我们无法预测什么会被破坏(或发生变化),而且我们也无法在发生错误的时候捕捉到错误的代码。

首先,我尝试了node_exporter的其他一些版本,并启用或禁用了不同的参数,但并没有什么效果。我还尝试在strace下运行实例,似乎没有发生崩溃,这强烈说明了这是在竞争条件下的一个问题。strace通常会拦截所有线程运行的所有系统调用,并在某种程度上让应用程序的执行串行化。后来,我发现strace也崩溃了,但是运行了很长时间才出现崩溃。由于这似乎与并发有关,所以我试着设置GOMAXPROCS=1,这个参数告诉Go只使用一个OS级别的线程来运行Go代码。崩溃再也没有发生,问题再一次指向了并发。

到目前为止,我已经收集了一定数量的崩溃日志,并开始关注其中的一些规律。虽然崩溃的位置以及表面原因有很多种,但是最终的错误信息可以分为多个不同的类型,而且每种类型的错误不止出现过一次。所以我开始使用谷歌搜索这些错误,并偶然间发现了Go issue #20427。虽然这个问题似乎与Go无关,但却引起了类似的段错误和随机性问题。在Go 1.9之后,这个问题被关闭了,但并没有得到解决。没有人知道根本原因是什么,而且它再也没有出现过。

所以,我从issue中抓取了这段声称能够重现问题的示例代码,并在我的机器上运行。你看,它在几秒钟内崩溃了。太好了。这比等待node_exporter崩溃所需的时间要短得多。

这并没有让我从Go的角度更接近这个问题,但它却加快了我测试的速度。所以,我们来试试从另一个角度进行分析吧。

把不同的电脑区分开来

这个问题发生在我的笔记本电脑上,但在其他机器上却都没有发生。我尝试着在其他电脑上重现这个问题,但没有一台机器发生崩溃。这说明我的笔记本电脑中有一些特别的东西。由于Go是静态链接的二进制文件,所以其余的用户空间并不重要。这留下了两个相关的部分:硬件和内核。

我没有什么方法来测试各台电脑的硬件,除了我自己的机器,但我可以捣鼓内核。所以,我们来试着走第一步:它会在虚拟机中崩溃吗?

为了测试这个,我创建了一个最小化的initramfs,这使我能够快速启动QEMU虚拟机,而不必安装发行版或启动完整的Linux系统。我的initramfs是用Linux的scripts/gen_initramfs_list.sh构建的,包含以下文件:

  1. dir /dev 755 0 0  
  2. nod /dev/console 0600 0 0 c 5 1  
  3. nod /dev/null 0666 0 0 c 1 3  
  4. dir /bin 755 0 0  
  5. file /bin/busybox busybox 755 0 0  
  6. slink /bin/sh busybox 755 0 0  
  7. slink /bin/true busybox 755 0 0  
  8. file /init init.sh 755 0 0  
  9. file /reproducer reproducer 755 0 0  
dir /dev 755 0 0
nod /dev/console 0600 0 0 c 5 1
nod /dev/null 0666 0 0 c 1 3
dir /bin 755 0 0
file /bin/busybox busybox 755 0 0
slink /bin/sh busybox 755 0 0
slink /bin/true busybox 755 0 0
file /init init.sh 755 0 0
file /reproducer reproducer 755 0 0


/init是Linux initramfs的入口,在我这个案例中是一个简单的shell脚本,用于启动测试并测量时间:

  1. #!/bin/sh  
  2. export PATH=/bin  
  3. start=$(busybox date +%s)  
  4. echo "Starting test now..."  
  5. /reproducer  
  6. ret=$?  
  7. end=$(busybox date +%s)  
  8. echo "Test exited with status $ret after $((end-start)) seconds"  
#!/bin/sh
export PATH=/bin

start=$(busybox date +%s)

echo "Starting test now..."
/reproducer
ret=$?
end=$(busybox date +%s)
echo "Test exited with status $ret after $((end-start)) seconds"


/bin/busybox是BusyBox的一个静态链接版本,通常用于这样的最小化系统,用以提供所有基本的Linux shell实用程序(包括shell本身)。

initramfs可以这样构建(从Linux内核源代码树中),其中,list.txt是上面的文件列表:

  1. scripts/gen_initramfs_list.sh -o initramfs.gz list.txt  
scripts/gen_initramfs_list.sh -o initramfs.gz list.txt


QEMU可以直接引导内核和initramfs:

  1. qemu-system-x86_64 -kernel /boot/vmlinuz-4.13.9-gentoo -initrd initramfs.gz -append 'console=ttyS0' -smp 8 -nographic -serial mon:stdio -cpu host -enable-kvm  
qemu-system-x86_64 -kernel /boot/vmlinuz-4.13.9-gentoo -initrd initramfs.gz -append 'console=ttyS0' -smp 8 -nographic -serial mon:stdio -cpu host -enable-kvm


并没有任何信息输出到控制台上…… 我意识到我没有为笔记本电脑内核编译8250串行端口支持。哦,我太蠢了。它根本没有物理串口,对吧?不管怎么样,我重新编译了内核,并附带串行支持。我再试了一下,它成功启动并运行了。

它崩溃了吗?是的。太好了,这意味着这个问题在同一台机器上的虚拟机上是可以重现的。我在家里的服务器上用同样的QEMU命令,用自己的内核,但什么也没有发生。然后,我从笔记本电脑中把内核复制过来,然后启动,崩溃了。内核是问题的关键,硬件不是问题。

捣鼓内核

我意识到自己需要编译许多的内核来尝试才能缩小范围,所以,我决定转移到一台最强大的机器上来:一个有点旧的12核24线程Xeon处理器的机器。我将已知的坏内核源复制到那台机器上,构建并进行测试。

它竟然没有崩溃!为什么?

在仔细思索了一番之后,我已经能够确定是原来的坏的内核二进制文件崩溃了。我们要回到分析硬件的问题上去吗?跟我在哪台机器上编译内核有关吗?所以,我试着在家用服务器上编译内核,接着,这个崩溃立即触发了。在两台机器上构建相同的内核会导致崩溃,而第三台机器不会。它们之间有什么不同呢?

我的笔记本电脑和家用服务器都是〜amd64(非稳定版),而我的Xeon服务器是amd64(稳定版)。这意味着它们的GCC是不同的。我的笔记本电脑和家用服务器都是gcc(Gentoo Hardened 6.4.0 p1.0)6.4.0,而我的Xeon是gcc(Gentoo硬件5.4.0-r3 p1.3,pie-0.6.5) 5.4.0。

但是我的家用服务器内核与笔记本电脑内核几乎是相同的(尽管不完全相同),使用相同的GCC构建,并没有重现崩溃。所以,现在我们必须得出结论:用来构建内核的编译器和内核本身(或其配置?)都有问题。

为了进一步缩小范围,我在家用服务器(linux-4.13.9-gentoo)上编译了笔记本电脑上的内核树,并确认它出现了崩溃。然后,我把家用服务器上的.config复制过来并编译,发现它没有崩溃。这么做是因为我们想要寻找内核配置之间的差异和编译器之间的差异:

  • linux-4.13.9-gentoo + gcc 5.4.0-r3 p1.3 + laptop .config - 没有崩溃
  • linux-4.13.9-gentoo + gcc 6.4.0 p1.0 + laptop .config - 崩溃
  • linux-4.13.9-gentoo + gcc 6.4.0 p1.0 + server .config - 没有崩溃

两个.config,一个好,一个坏。需要一点时间来查看它们之间的差异。当然,这两个配置文件是完全不同的(因为我喜欢定制我的内核配置,让它只包含特定机器上所需的驱动程序),所以我不得不在重复编译内核来缩小差异。

我决定从“坏”的.config开始着手,从中删除一些东西。由于要测试崩溃需要等待一定的时间,所以测试“崩溃”比“不崩溃”更容易。在22个内核的构建过程中,我对config文件做了简化,使其不支持网络、没有文件系统、没有块设备核心,甚至不支持PCI(但它仍然可以在虚拟机上正常工作!)。现在编译一下内核不到60秒的时间,内核大小大约是我常用内核的四分之一左右。

然后,我转移到“好”的.config文件上来,删除了所有不必要的垃圾,同时确保它不会崩溃(这比之前的测试更加棘手更加慢)。也有一些有问题的分支,我在这些分支上修改了一些东西,接着就开始崩溃了。但是,我误认为这些分支是“不会崩溃”的。所以,当崩溃发生的时候,我不得不找回以前的内核,并找出引起崩溃的确切的原因。最后,我一共编译了7个内核。

最后,我把范围缩小到.config中的几个不同的选项上来。其中有几个嫌疑很大,特别是CONFIG_OPTIMIZE_INLINING。经过仔细地测试,我得出结论:这个选项就是罪魁祸首。把它关掉,就会产生崩溃,启用,就不会崩溃。这个选项在打开的时候允许GCC自己确定哪个inline函数真的需要内联,而不是强制内联。这也解释了:内联行为可能随着GCC版本的不同而不同。

  1.  * Force always-inline if the user requests it so via the .config,  
  2.  * or if gcc is too old.  
  3.  * GCC does not warn about unused static inline functions for  
  4.  * -Wunused-function.  This turns out to avoid the need for complex #ifdef  
  5.  * directives.  Suppress the warning in clang as well by using "unused"  
  6.  * function attribute, which is redundant but not harmful for gcc.  
  7. #if !defined(CONFIG_ARCH_SUPPORTS_OPTIMIZED_INLINING) ||                \  
  8.     !defined(CONFIG_OPTIMIZE_INLINING) || (__GNUC__ < 4)  
  9. #define inline inline           __attribute__((always_inline,unused)) notrace  
  10. #define __inline__ __inline__   __attribute__((always_inline,unused)) notrace  
  11. #define __inline __inline       __attribute__((always_inline,unused)) notrace  
  12. #else  
  13. /* A lot of inline functions can cause havoc with function tracing */  
  14. #define inline inline           __attribute__((unused)) notrace  
  15. #define __inline__ __inline__   __attribute__((unused)) notrace  
  16. #define __inline __inline       __attribute__((unused)) notrace  
  17. #endif  
/*
 * Force always-inline if the user requests it so via the .config,
 * or if gcc is too old.
 * GCC does not warn about unused static inline functions for
 * -Wunused-function.  This turns out to avoid the need for complex #ifdef
 * directives.  Suppress the warning in clang as well by using "unused"
 * function attribute, which is redundant but not harmful for gcc.
 */
#if !defined(CONFIG_ARCH_SUPPORTS_OPTIMIZED_INLINING) ||                \
    !defined(CONFIG_OPTIMIZE_INLINING) || (__GNUC__ < 4)
#define inline inline           __attribute__((always_inline,unused)) notrace
#define __inline__ __inline__   __attribute__((always_inline,unused)) notrace
#define __inline __inline       __attribute__((always_inline,unused)) notrace
#else
/* A lot of inline functions can cause havoc with function tracing */
#define inline inline           __attribute__((unused)) notrace
#define __inline__ __inline__   __attribute__((unused)) notrace
#define __inline __inline       __attribute__((unused)) notrace
#endif


那么接下来做什么呢? 我们知道CONFIG_OPTIMIZE_INLINING这个选项使得测试结果出现不同,但是它可能会改变整个内核中每一个inline的行为。 如何查明问题的真相呢?

我有一个主意。

基于散列的差异化编译

我们要做的是在选项打开的情况下编译内核的一部分,在选项关闭的情况下编译另一部分。 通过测试生成的内核并检查问题是否重现,可以推导出内核编译单元的哪个子集的代码有问题。

我没有列举出所有的目标文件,或是进行某种二分法搜索,而是决定采用基于散列的方法。 我为GCC编写了这个包装器脚本:

  1. #!/bin/bash  
  2. args=("$@")  
  3. doit=  
  4. while [ $# -gt 0 ]; do  
  5.         case "$1" in  
  6.                         doit=1  
  7.                         shift  
  8.                         objfile="$1"  
  9.         shift  
  10. extra=  
  11. if [ ! -z "$doit" ]; then  
  12.         sha="$(echo -n "$objfile" | sha1sum - | cut -d" " -f1)"  
  13.         echo "${sha:0:8} $objfile" >> objs.txt  
  14.         if [ $((0x${sha:0:8} & (0x80000000 >> $BIT))) = 0 ]; then  
  15.                 echo "[n]" "$objfile" 1>&2  
  16.                 extra=-DCONFIG_OPTIMIZE_INLINING  
  17.                 echo "[y]" "$objfile" 1>&2  
  18. exec gcc $extra "${args[@]}"  
#!/bin/bash
args=("$@")

doit=
while [ $# -gt 0 ]; do
        case "$1" in
                -c)
                        doit=1
                        ;;
                -o)
                        shift
                        objfile="$1"
                        ;;
        esac
        shift
done

extra=
if [ ! -z "$doit" ]; then
        sha="$(echo -n "$objfile" | sha1sum - | cut -d" " -f1)"
        echo "${sha:0:8} $objfile" >> objs.txt
        if [ $((0x${sha:0:8} & (0x80000000 >> $BIT))) = 0 ]; then
                echo "[n]" "$objfile" 1>&2
        else
                extra=-DCONFIG_OPTIMIZE_INLINING
                echo "[y]" "$objfile" 1>&2
        fi
fi

exec gcc $extra "${args[@]}"


这个脚本使用SHA-1来取目标文件名的散列值,然后从前32位中检查散列的给定位(由环境变量$BIT进行标识)。 如果这个位的值是0,则编译的时候不带CONFIG_OPTIMIZE_INLINING, 如果是1,则带上CONFIG_OPTIMIZE_INLINING。 我发现内核大约有685个目标文件,这需要大约10个位来进行唯一标识。 这种基于散列的方法有一个很好的属性:我可以选择产生崩溃可能性比较大的结果(即位的值是0),因为要证明给定的内核不会崩溃是很困难的(因为崩溃是概率性出现的, 可能需要相当一段时间才会发生)。

我构建了32个内核,只花了29分钟的时间。然后,我开始对它们进行测试,每当发生崩溃的时候,我都会将可能的SHA-1散列的正则表达式缩小到那些在这些特定位置上是0的散列。在发生了8次崩溃的时候,我把范围缩小到4个目标文件。一旦出现了10次崩溃之后,就只剩下唯一的一个了。

  1. $ grep '^[0246][012389ab][0189][014589cd][028a][012389ab][014589cd]' objs_0.txt  
  2. 6b9cab4f arch/x86/entry/vdso/vclock_gettime.o  
$ grep '^[0246][012389ab][0189][014589cd][028a][012389ab][014589cd]' objs_0.txt
6b9cab4f arch/x86/entry/vdso/vclock_gettime.o


vDSO的代码。当然。

vDSO在捣鬼

内核的vDSO实际上并不算是内核代码。 vDSO是内核放置在每个进程地址空间中的一个小型共享库,它允许应用程序在不离开用户模式的情况下执行特定的系统调用。这大大提高了系统性能,同时仍然允许内核根据需要更改这些系统调用的实现细节。

换句话说,vDSO是用GCC编译的代码,与内核一起构建,最终与每个用户空间的应用程序进行链接。它是用户空间的代码。这就解释了为什么内核和它的编译器都与此有关:这并不是跟内核本身有关,而是与内核提供的共享库有关! Go使用vDSO来提升性能。Go也正好有一个重建自己的标准库的战略,所以,它没有使用任何标准的Linux glibc的代码来调用vDSO,而是使用了自己的代码。

那么改变CONFIG_OPTIMIZE_INLINING的值对vDSO有什么作用呢?我们来看看这段汇编。

设置CONFIG_OPTIMIZE_INLINING = n:

  1. arch/x86/entry/vdso/vclock_gettime.o.no_inline_opt:     file format elf64-x86-64  
  2. Disassembly of section .text:  
  3. 0000000000000000 <vread_tsc>:  
  4.    0:   55                      push   %rbp  
  5.    1:   48 89 e5                mov    %rsp,%rbp  
  6.    4:   90                      nop  
  7.    5:   90                      nop  
  8.    6:   90                      nop  
  9.    7:   0f 31                   rdtsc    
  10.    9:   48 c1 e2 20             shl    $0x20,%rdx  
  11.    d:   48 09 d0                or     %rdx,%rax  
  12.   10:   48 8b 15 00 00 00 00    mov    0x0(%rip),%rdx        # 17 <vread_tsc+0x17>  
  13.   17:   48 39 c2                cmp    %rax,%rdx  
  14.   1a:   77 02                   ja     1e <vread_tsc+0x1e>  
  15.   1c:   5d                      pop    %rbp  
  16.   1d:   c3                      retq     
  17.   1e:   48 89 d0                mov    %rdx,%rax  
  18.   21:   5d                      pop    %rbp  
  19.   22:   c3                      retq     
  20.   23:   0f 1f 00                nopl   (%rax)  
  21.   26:   66 2e 0f 1f 84 00 00    nopw   %cs:0x0(%rax,%rax,1)  
  22.   2d:   00 00 00   
  23. 0000000000000030 <__vdso_clock_gettime>:  
  24.   30:   55                      push   %rbp  
  25.   31:   48 89 e5                mov    %rsp,%rbp  
  26.   34:   48 81 ec 20 10 00 00    sub    $0x1020,%rsp  
  27.   3b:   48 83 0c 24 00          orq    $0x0,(%rsp)  
  28.   40:   48 81 c4 20 10 00 00    add    $0x1020,%rsp  
  29.   47:   4c 8d 0d 00 00 00 00    lea    0x0(%rip),%r9        # 4e <__vdso_clock_gettime+0x1e>  
  30.   4e:   83 ff 01                cmp    $0x1,%edi  
  31.   51:   74 66                   je     b9 <__vdso_clock_gettime+0x89>  
  32.   53:   0f 8e dc 00 00 00       jle    135 <__vdso_clock_gettime+0x105>  
  33.   59:   83 ff 05                cmp    $0x5,%edi  
  34.   5c:   74 34                   je     92 <__vdso_clock_gettime+0x62>  
  35.   5e:   83 ff 06                cmp    $0x6,%edi  
  36.   61:   0f 85 c2 00 00 00       jne    129 <__vdso_clock_gettime+0xf9>  
  37. [...]  
arch/x86/entry/vdso/vclock_gettime.o.no_inline_opt:     file format elf64-x86-64


Disassembly of section .text:

0000000000000000 <vread_tsc>:
   0:   55                      push   %rbp
   1:   48 89 e5                mov    %rsp,%rbp
   4:   90                      nop
   5:   90                      nop
   6:   90                      nop
   7:   0f 31                   rdtsc  
   9:   48 c1 e2 20             shl    $0x20,%rdx
   d:   48 09 d0                or     %rdx,%rax
  10:   48 8b 15 00 00 00 00    mov    0x0(%rip),%rdx        # 17 <vread_tsc+0x17>
  17:   48 39 c2                cmp    %rax,%rdx
  1a:   77 02                   ja     1e <vread_tsc+0x1e>
  1c:   5d                      pop    %rbp
  1d:   c3                      retq   
  1e:   48 89 d0                mov    %rdx,%rax
  21:   5d                      pop    %rbp
  22:   c3                      retq   
  23:   0f 1f 00                nopl   (%rax)
  26:   66 2e 0f 1f 84 00 00    nopw   %cs:0x0(%rax,%rax,1)
  2d:   00 00 00 

0000000000000030 <__vdso_clock_gettime>:
  30:   55                      push   %rbp
  31:   48 89 e5                mov    %rsp,%rbp
  34:   48 81 ec 20 10 00 00    sub    $0x1020,%rsp
  3b:   48 83 0c 24 00          orq    $0x0,(%rsp)
  40:   48 81 c4 20 10 00 00    add    $0x1020,%rsp
  47:   4c 8d 0d 00 00 00 00    lea    0x0(%rip),%r9        # 4e <__vdso_clock_gettime+0x1e>
  4e:   83 ff 01                cmp    $0x1,%edi
  51:   74 66                   je     b9 <__vdso_clock_gettime+0x89>
  53:   0f 8e dc 00 00 00       jle    135 <__vdso_clock_gettime+0x105>
  59:   83 ff 05                cmp    $0x5,%edi
  5c:   74 34                   je     92 <__vdso_clock_gettime+0x62>
  5e:   83 ff 06                cmp    $0x6,%edi
  61:   0f 85 c2 00 00 00       jne    129 <__vdso_clock_gettime+0xf9>
[...]


设置CONFIG_OPTIMIZE_INLINING=y:

  1. arch/x86/entry/vdso/vclock_gettime.o.inline_opt:     file format elf64-x86-64  
  2. Disassembly of section .text:  
  3. 0000000000000000 <__vdso_clock_gettime>:  
  4.    0:   55                      push   %rbp  
  5.    1:   4c 8d 0d 00 00 00 00    lea    0x0(%rip),%r9        # 8 <__vdso_clock_gettime+0x8>  
  6.    8:   83 ff 01                cmp    $0x1,%edi  
  7.    b:   48 89 e5                mov    %rsp,%rbp  
  8.    e:   74 66                   je     76 <__vdso_clock_gettime+0x76>  
  9.   10:   0f 8e dc 00 00 00       jle    f2 <__vdso_clock_gettime+0xf2>  
  10.   16:   83 ff 05                cmp    $0x5,%edi  
  11.   19:   74 34                   je     4f <__vdso_clock_gettime+0x4f>  
  12.   1b:   83 ff 06                cmp    $0x6,%edi  
  13.   1e:   0f 85 c2 00 00 00       jne    e6 <__vdso_clock_gettime+0xe6>  
  14. [...]  
arch/x86/entry/vdso/vclock_gettime.o.inline_opt:     file format elf64-x86-64


Disassembly of section .text:

0000000000000000 <__vdso_clock_gettime>:
   0:   55                      push   %rbp
   1:   4c 8d 0d 00 00 00 00    lea    0x0(%rip),%r9        # 8 <__vdso_clock_gettime+0x8>
   8:   83 ff 01                cmp    $0x1,%edi
   b:   48 89 e5                mov    %rsp,%rbp
   e:   74 66                   je     76 <__vdso_clock_gettime+0x76>
  10:   0f 8e dc 00 00 00       jle    f2 <__vdso_clock_gettime+0xf2>
  16:   83 ff 05                cmp    $0x5,%edi
  19:   74 34                   je     4f <__vdso_clock_gettime+0x4f>
  1b:   83 ff 06                cmp    $0x6,%edi
  1e:   0f 85 c2 00 00 00       jne    e6 <__vdso_clock_gettime+0xe6>
[...]


有趣的是,CONFIG_OPTIMIZE_INLINING=y这个本应该让GCC内联变少的标志,实际上却让内联变得更多:vread_tsc在该版本中内联,而不在CONFIG_OPTIMIZE_INLINING=n版本中。但是vread_tsc根本没有标记为内联,所以GCC完全有权限这么做。

但谁在乎函数是否内联了呢?真正的问题在哪里呢?那么,仔细观察一下非内联版本吧……

  1. 30:   55                      push   %rbp  
  2.  31:   48 89 e5                mov    %rsp,%rbp  
  3.  34:   48 81 ec 20 10 00 00    sub    $0x1020,%rsp  
  4.  3b:   48 83 0c 24 00          orq    $0x0,(%rsp)  
  5.  40:   48 81 c4 20 10 00 00    add    $0x1020,%rsp  
 30:   55                      push   %rbp
  31:   48 89 e5                mov    %rsp,%rbp
  34:   48 81 ec 20 10 00 00    sub    $0x1020,%rsp
  3b:   48 83 0c 24 00          orq    $0x0,(%rsp)
  40:   48 81 c4 20 10 00 00    add    $0x1020,%rsp


为什么GCC会分配超过4KB的栈呢?这不是栈分配,这是栈探测,或者更具体地说是GCC-fstack-check特性的结果。

Gentoo Linux在默认的配置文件中启用了-fstack-check。这是为了规避Stack Clash漏洞。-fstack-check是GCC的一个很老的功能,它有一个副作用,会引发一些非常愚蠢的行为,每个非叶子函数(也就是一个函数调用的函数)只会探测栈指针前4KB的空间。换句话说,用-fstack-check编译的代码可能至少需要4 KB的栈空间,除非它是一个叶子函数。

Go喜欢小巧的栈。

  1. TEXT runtime·walltime(SB),NOSPLIT,$16  
  2.     // Be careful. We're calling a function with gcc calling convention here.  
  3.     // We're guaranteed 128 bytes on entry, and we've taken 16, and the  
  4.     // call uses another 8.  
  5.     // That leaves 104 for the gettime code to use. Hope that's enough!  
TEXT runtime·walltime(SB),NOSPLIT,$16
    // Be careful. We're calling a function with gcc calling convention here.
    // We're guaranteed 128 bytes on entry, and we've taken 16, and the
    // call uses another 8.
    // That leaves 104 for the gettime code to use. Hope that's enough!


实际上,104个字节并不是对每个人都够用,对我的内核来说也一样。

需要指出的是,vDSO的规范没有提到最大的栈使用保证,所以,Go做了一个无效的假设。

结论

这完美地诠释了问题出现的原因。栈探测器是一个orq,它是跟0做逻辑或运算。这是一个无操作,但有效地探测了目标地址(如果它是未映射的,就会出现段错误)。但是我们没有在vDSO代码中看到段错误,那么Go为什么会出现呢?实际上,跟0做逻辑或运算并不是真的无操作。由于orq不是一个原子指令,而实际上是CPU读取内存地址,然后再写回来。这时候就出现了竞争条件。如果其他线程在其他的CPU上并行运行,那么orq就可能会消除同时发生的内存写操作。由于写入超出了栈的边界,这可能会侵入其他线程的栈或随机数据。这也是为什么GOMAXPROCS=1能够解决这个问题的原因,因为这可以防止两个线程同时运行Go代码。

那么怎么修复呢?我把这留给了Go的开发人员。他们最终的解决方案是在调用vDSO函数之前转到更大的栈上。这会引入了一个小小的速度延迟(纳秒级),但这是可以接受的。在用修复过的Go工具链构建node_exporter之后,崩溃消失了。


About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK