分享工作中重要的经历，可以当小说来看
一、伪内存泄漏排查
1.1 背景
我们原来有一个刚用 C++ 写的业务服务，迟迟不敢上线，原因是内存泄漏问题一直解决不了。现象是，服务上线后，内存一直慢慢每隔几秒上涨4/8KB，直到服务下线。
我刚入职不久，领导让我来查这个问题，非常具有挑战性，也是领导对我的考察！
1.2 分析
心路历程1：工具分析
使用 Valgrind 跑 N 遍服务，结果中都没有发现内存泄漏，但是有很多没有被释放的内存和很多疑似内存泄漏。实在没有发现线索。
心路历程2：逐个模块排查
工具分析失败，那就挨个模块翻看代码，并且逐个模块写demo验证该模块是否有泄漏（挂 Valgrind），很遗憾，最后还是没有找到内存泄漏。
心路历程3：不抛弃不放弃
这个时候两周快过去了，领导说：“找不到内存泄漏那就先去干别的任务吧”，感觉到一丝凉意，我说：“再给我点时间，快找到了”。这样顶着巨大压力加班加点的跑Valgrind，拿多次数据结果进行对比，第一份跑 10 分钟，第二份跑 20 分钟，看看有哪些差异或异常，寻找蛛丝马迹。遗憾的是还是没有发现内存泄漏在哪。
功夫不负有心人，看了 N 份结果后，对一个队列产生了疑问，它为啥这么大，队列长度 1000 万，直觉告诉我，它不正常。
去代码中找这个队列，确实在初始化的时候设置了 1000 万长度，这个长度太大了。
1.3 定位
进队列需要把虚拟地址映射到物理地址，物理内存就会增加，但是出队列物理内存不会立刻回收，而是保留给程序一段时间（当系统内存紧张时会主动回收），目的是让程序再次使用之前的虚拟地址更快，不需要再次申请物理内存映射了，直接使用刚才要释放的物理内存即可。
当服务启动时，程序在这 1000 万队列上一直不停的进/出队列，有点像貔貅，光吃不拉，物理内存自然会一直涨，直到貔貅跑到了队尾，物理内存才会达到顶峰，开始处在一个平衡点。
图1 中，红色代表程序占用的物理内存，绿色为虚拟内存。
图1
然而每次上线还没等 到达平衡点前就下线了，担心服务内存一直涨，担心出事故就停服务了。解决办法就是把队列长度调小，最后调到了 2 万，再上线，貔貅很快跑到了队尾，达到了平衡点，内存就不再增涨。
其实，本来就没有内存泄漏，这就是伪内存泄漏。
二、周期性事故处理
2.1 背景
我们有一个业务，2019 年到 2020 年间发生四次（1025、0322、0511 和 0629）大流量事故，事故时网络流量理论峰值 3000 Gbps，导致网络运营商封禁入口 IP，造成几百万元经济损失，均没有找到具体原因，一开始怀疑是服务器受到网络攻击。
后来随着事故发生次数增加，发现事故发生时间具有规律性，越发感觉不像是被攻击，而是业务服务本身的流量瞬间增多导致。服务指标都是事故造成的结果，很难倒推出事故原因。
2.2 猜想（大胆假设）
2.2.1 发现事故大概每50天发生一次
清晰记得 2020 年 7 月 15 日那天巡检服务时，我把 snmp.xxx.InErrors 指标拉到一年的跨度，如图2 发现多个尖刺的间距似乎相等，然后我就看了下各个尖刺时间节点，记录下来，并且具体计算出各个尖刺间的间隔记录在下面表格中。着实吓了一跳，大概是 50 天一个周期。并且预测了 8月18日 可能还有一次事故。
图2 服务指标
| 事故时间 | 相隔天数 |
|---|---|
| 2019.09.05 | - |
| 2019.10.25 | 50天 |
| 2019.12.14 | 50天 |
| 2020.02.01 | 49天 |
| 2020.03.22 | 50天 |
| 2020.05.11 | 50天 |
| 2020.06.29 | 49天 |
| 2020.08.18 | 预计 |
2.2.2 联想50天与uint溢出有关
7 月 15 日下班的路上，我在想 3600（一个小时的秒数），86400（一天的秒数），50 天，5 x 8 等于 40，感觉好像和 42 亿有关系，那就是 uint（2^32），就往上面靠，怎么才能等于 42 亿，86400 x 50 x 1000 是 40 多亿，这不巧了嘛！拿出手机算了三个数：
2^32 = 4294967296
3600 * 24 * 49 * 1000 = 4233600000
3600 * 24 * 50 * 1000 = 4320000000
好巧，2^32 在后面的两个结果之间，4294967296 就是 49 天 16 小时多些，验证了大概每 50 天发生一次事故的猜想。
图3 联想过程
2.3 定位（小心求证）
2.3.1 翻看代码中与时间相关的函数
果然找到一个函数有问题，下面的代码，在 64 位系统上没有问题，但是在 32 位系统上会发生溢出截断，导致返回的时间是跳变的，不连续。图4 是该函数随时间输出的折线图，理想情况下是一条向上的蓝色直线，但是在 32 位系统上，结果却是跳变的红线。
uint64_t now_ms() {
struct timeval t;
gettimeofday(&t, NULL);
return t.tv_sec * 1000 + t.tv_usec / 1000;
}
图4 函数输出
这里解释一下，问题出在了 t.tv_sec * 1000，在 32 位系统上会发生溢出，高于 32 位的部分被截断，数据丢失。不幸的是我们的客户端有一部分是 32 位系统的。
2.3.2 找到出问题的逻辑
继续追踪使用上面函数的逻辑，发现一处问题，客户端和服务端的长链接需要发Ping保活，下一次发Ping时间等于上一次发Ping时间加上 30 秒，代码如下：
next_ping = now_ms() + 30000;
客户端主循环会不断判断当前时间是否大于 next_ping，当大于时发 Ping 保活，代码如下：
if (now_ms() > next_ping) {
send_ping();
next_ping = now_ms() + 30000;
}
那怎么就出现大流量打到服务器呢？举个例子，如图3，假如当前时间是 6月29日 20:14:00（20:14:26 时 now_ms 函数返回 0），now_ms 函数的返回值超级大。
那么 next_ping 等于 now_ms() 加上 30000（30s），结果会发生 uint64 溢出，反而变的很小，这就导致在接下来的 26 秒内，now_ms函数返回值一直大于 next_ping，就会不停发 Ping 包，产生了大量流量到服务端。
2.3.3 客户端实际验证
找到一个有问题的客户端设备，把它本地时间拨回 6月29日 20:13:00，让其自然跨过 20:14:26，发现客户端本地 log 中有大量发送 Ping 包日志，8 秒内发送 2 万多个包。证实事故原因就是这个函数造成的。解决办法是对 now_ms 函数做如下修改：
uint64_t now_ms() {
struct timespec t;
clock_gettime(CLOCK_MONOTONIC, &t);
return uint64_t(t.tv_sec) * 1000 + t.tv_nsec / 1000 / 1000;
}
2.3.4 精准预测后面事故时间点
因为客户端发版周期比较长，需要做好下次事故预案，及时处理事故，所以预测了后面多次事故。
| 时间戳（ms） | 16进制 | 北京时间 | 备注 |
|---|---|---|---|
| 1571958030336 | 0x16E00000000 | 2019/10/25 07:00:30 | 历史事故时间 |
| 1576252997632 | 0x16F00000000 | 2019/12/14 00:03:17 | 不确定 |
| 1580547964928 | 0x17000000000 | 2020/02/01 17:06:04 | 不确定 |
| 1584842932224 | 0x17100000000 | 2020/03/22 10:08:52 | 历史事故时间 |
| 1589137899520 | 0x17200000000 | 2020/05/11 03:11:39 | 历史事故时间 |
| 1593432866816 | 0x17300000000 | 2020/06/29 20:14:26 | 历史事故时间 |
| 1597727834112 | 0x17400000000 | 2020/08/18 13:17:14 | 精准预测事故发生 |
| 1602022801408 | 0x17500000000 | 2020/10/07 06:20:01 | 精准预测事故发生 |
| 1606317768704 | 0x17600000000 | 2020/11/25 23:22:48 | 精准预测事故发生 |
2.4 总结
该事故的难点在于大部分服务端的指标都是事故导致的结果，并且大流量还没有到业务服务，就被网络运营商封禁了 IP；并且事故周期跨度大，50 天发生一次，发现规律比较困难。
发现规律是第一步，重点是能把 50 天和 uint32 的最大值联系起来，这一步是解决该问题的灵魂。
- 大胆假设：客户端和服务端的代码中与时间相关的函数有问题；
- 小心求证：找到有问题的函数，别写代码验证，最后通过复现定位问题；
经过不屑努力从没有头绪到逐渐缩小排查范围，最后定位和解决问题。
作者：科英
来源：juejin.cn/post/7252159509837119546
