浴室沉思:Debug 什么问题最爽

毕业已经四年多了,想想我 debug 成功或失败的大小问题应该数不胜数。浴室沉思:debug 什么样的问题是最爽的?


我对复杂问题有两种归类:一种类似网游、竞技游戏,规则复杂、设定丰富、不确定因素更多,好比现实中的混沌理论;另一种类似围棋、传送门这种游戏,规则有限、设定极少、谜面完全确定,但解法可以很复杂,好比真空中的球形鸡。

两个例子:

  1. 为什么删掉十年前没有被任何地方引用的另一个项目的代码,看起来毫无影响的项目的新代码就坏掉了?
  2. 某处限制了64KB大小,但我们的数据即使用常用的二进制编码格式仍然可能超过这个大小;我们有 5% 的数据可能会超过这个大小,怎么改代码是更合理的?

后者显然求解起来更爽,我也更喜欢做后者描述的问题。但解开以后的成就感呢?我只能说我现在印象深刻的问题好像都是前者。


另一个很重要的事情是,和别人讲这个问题的时候什么类型的问题更有成就感?

它确实是「爽」的重要组成部分

我解决过一些奇奇怪怪的并发先后问题、难复现的用户场景问题、奇葩的边界条件问题,但这些都不是我乐意和别人说的东西。

说这些东西的成就感不会很高,是因为这种问题有时就是蒙出来的(即使我会觉得自己蒙的很有艺术性),但大家都能蒙。就算我给别人描述其中的逻辑有多复杂、层级有多深,或许对方只会觉得「屎山代码嘛,我公司代码库里还有 20 年前没有人敢动的代码呢」。


如果有人问「你解决过的最有意思的问题是什么」,我通常会回答下面中的一个。

一、欧洲用户问题

背景(已简化)

扇贝单词是一个背单词 APP;一个重要功能是完成当天的学习任务后,当天可以打卡;用户都是在自己的当地时区的自然天打卡。

问题

一些用户某天开始突然不能打卡

一筹莫展

收集了一些用户反馈,发现他们都是欧洲的用户;而且都在自己当地时区的 0 点附近尝试打卡失败;也就是说用户在当地时间并没有度过当天 24 点,但我们系统认为他已经度过了当天 24 点,不允许打前一天的卡。

第一直觉是时区相关的代码逻辑出问题,检查后发现这部分代码并没有人动过。

第二直觉就是和夏冬令时有关,恰好出问题前几天欧洲从夏令时切到冬令时。但:时区相关的代码没有人动过;往年夏冬令时切换并没有出现问题;美国用户也不少,美国很多州也有夏冬令时,却完全正常。

欧洲特例?

就在一筹莫展之际,我突然想到几年前看过一个新闻,印象中欧盟通过了一项决议,会在 2020 年取消夏冬令时。那是不是意味着有可能他们的法令执行了,代码里的时区信息却没有更新?

但是:

  • 当时使用的是最新的 go 1.14,彼时 go 语言还没有加入 tzdata 标准库
  • 所以代码里的时区信息来源,是在每次打包镜像时 alpine 里安装的 tzdata;我们安装的 tzdata 已经是最新版,要是有问题全世界用到 tzdata 的服务应该都爆炸了才对

而且:

  • 重新搜索这个新闻,发现欧盟已经取消这个「2020 年取消夏冬令时」的决议了。

这下更怪了。

反向思考

那是不是有可能,现实中的欧盟已经取消执行了,tzdata 却还是按照原本的决议执行了呢?

nonono,还是一样的问题:如果 tzdata 的数据不对,全世界都应该爆炸了,不应该只有我们在抱怨。

尝试复现

要确定是时区相关的问题,还是需要复现证明一下。似乎本地安装最新版 tzdata,用 go 写一个例子打印欧洲某地的时区尝试复现一下就好。

但复现成功是一个非常偶然的状况。

我当时在本地运行打印时间的代码,一切都是正确符合预期的;直到(已经不记得是怎么发生的了,大概是同事提醒)尝试在 alpine 容器里编译同样的代码,执行,打印出来的时间却和当地现实时间差一小时!

在 tzdata 版本一模一样的状况下!

复现成功以后一切就水到渠成。我们做更多测试,来判断是编译期的问题还是运行期的问题、是不是 apline 的安装问题等等。

结论

alpine 上安装的 tzdata 里的信息是正确的;它在欧盟开始决议后更新了信息;欧盟取消决议后也附加上了取消决议的信息。

实际问题是,alpine 上的 tzdata 包用了和其他地方不一样的格式(或语法?已经记不太清了)。这种取消再取消的格式比较新,当时的 go 1.14 能读取到「在 2020 年取消夏冬令时」这个信息,但读不出来「取消「在 2020 年取消夏冬令时」」这个信息。导致实际在 alpine 环境里,go 1.14 的程序认为这项法令已经执行了。

最后的解决方案是:

  • 把 base image 换成了 ubuntu,tzdata 版本没变,一切运行正常
  • go 1.15 当时马上就要出了,这个新格式也能正常读取;有一些人反馈以后(很多天),给 1.14 增加了一个小版本 backport 解决了这个问题
  • go 1.15 自带了 tzdata。但我想,用半年一更新的语言标准库带的时区信息怎么跟得上变幻莫测的现实世界呢?

PS: 之所以在「背景」这一节加上了已简化三个字,是因为实际后端逻辑是:允许用户在连续背单词超过当地 0 点但不超过 1 点时,仍然可以打前一天的卡……

加上这个逻辑以后,是不是觉得 debug 的复杂度上去了一截……

二、有概率发生的性能问题

由于写到这里我已经觉得太长想摆烂了,下面我就摆烂了

这个问题的结论是阿里云同样规格的某些云服务器,在一些条件下单核性能会比其他低 30%

三、CI 环境里编译 go 代码特别慢

这个问题的结论是 CI 环境里的机器的 CPU 没有 AVX 指令集;go 代码里引入了 C++ 代码一起编译,其中一些使用 AVX 指令会编译的非常快,没有就非常慢。

四、未解之谜

一段 go 代码会声明读写一些数组,它们的生命周期就是一个请求的生命周期;这段代码在生产环境会内存泄露,但很慢,一天几十 M,但永远不会下降直到重启。

使用 go 语言的 profile 和 metrics 采集观测不到,但观测操作系统里这个进程的 RSS 指标会看到。

本地测试非常多次完全无法复现状况,比生产环境更大的暴力压测都不行(或者说有时似乎复现了,但解决方案放到生产环境并没有用)。

已知的:

  • 有一些数组可能很长几十万字节,有一些则很短;不论我们一开始声明很长的变量,或是一个个 append 都会发生内存泄漏
  • 代码逻辑里不存在全局变量或者其他导致泄露的问题
  • 在 go 程序里手动释放内存、标记 madvdontneed 等等,问题依然存在(当时已经在使用 1.16)
  • 确认了我们的 go 程序会执行 Linux 的 MADV_DONTNEED 指令而不是 MADV_FREE、更新了宿主机的 Linux 内核版本

怀疑是 go 的内存模型和 linux 的某些机制导致的泄露(碎片?),但彼时已经 debug 超过一周仍然没有成效,而且问题似乎已经过于底层触及了我的知识盲区。最终仅仅是限制了数组的大小,逻辑完全不变的情况下,问题解决,再也没有内存泄露。