有一个 bug 查了将近 2 个月。
有一个业务操作不能超过 1s，实际上通常只耗时 10ms 以内。但在 10 万次操作中，有可能出现 1 次耗时 2s 左右。
涉及的代码有用户空间、网络通信、内核，运行在不同的板子、不同的 CPU 上，CPU/板子之间用以太网通信。
一开始怀疑是以太网延迟导致的，但找不到证据。
后来想办法缩小范围，加上研究代码，怀疑到跟日志有关。业务操作在处理过程中会写日志。日志临时放在内存 buffer 里，写满了就调用压缩算法 dump 到磁盘上。把压缩算法去掉、或者干脆不 dump 日志，问题就不复现。另外统计了 dump 日志的耗时，正好是 2s 左右。于是怀疑到压缩算法占用了 CPU。但很快否定，因为这个线程的优先级很低，调度策略也是后台类型的，根本抢不过实时调度策略的业务线程。在内核里启用 ftrace 也证实了不是 CPU 抢占导致的。
但 dump 日志正好耗时 2s 跟业务线程耗时 2s 之间似乎不是巧合。再研究代码，访问日志 buffer 时会有互斥锁 (mutex) 保护。Dump 日志的时候，会加锁；向其中写日志时，也会加锁。把互斥锁去掉，也不复现了。于是检查对互斥锁的使用是否正确。业务线程在处理业务时，会写日志，自然就会去加锁，但它用的是
pthread_mutex_timedlock()
最多等待 10ms，等不到 mutex 就放弃。理论上这也不会导致耗时 2s。
但可疑点不能就这么放过，接下来调试写日志的函数本身。调用最原始的
sprintf()
把调试信息写到内存里，等出现问题时，再把这块内存 dump 出来。通过查看调试信息里的时间戳，发现这 2s 消耗在上面提到的
pthread_mutex_timedlock()
里。
至此，快要找到原因了。编写一个单元测试程序，验证 glibc 对
pthread_mutex_timedlock()
的实现是否有 bug. 奇怪的是在 x64 服务器上，这个函数确实最多等待 10ms 就返回了。后来突然想到，目标代码运行在 MIPS 架构的 CPU 上。于是交叉编译一份 MIPS 程序，上机一测试，复现了。
再去查询 glibc release history, 有一个版本提到修复了
pthread_mutex_timedlock()
在 ARM CPU 上死等的 bug. 把这个修复移植过来，MIPS CPU 上的问题也解决了。
2019/11/19 更新：
补充一下这个 glibc bug 的报告（不是我报的） https:// sourceware.org/bugzilla /show_bug.cgi?id=20263
glibc v2.24 有描述修改该 bug: https://www. sourceware.org/ml/libc- alpha/2016-08/msg00212.html 有这样一句 "[20263] nptl: robust mutex deadlocks if other thread requests timedlock (Only arm/linux)"
好多人说这不是一个简单的 bug, 再说一个真的很简单的 bug（同事分享的）：DSP 莫名其妙死机，也是查了很久，发现问题在这里：
const char * array[ARRAY_SIZE] = {
"string 1",
"string 2",
"string 3",
/* ... */
"string n - 1"
"string n"
};
仔细看看，可以发现的。
