有一個 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"
};
仔細看看，可以發現的。
