18
王者榮耀
找bug記(2)
這篇blog遲到了很久，本來是想寫另一個跟網絡相關bug的查找過程，偷偷懶，寫下最近印象比較深刻的bug。這個bug是我的同事水寒最終定位到的。前幾個月同事報告稱有一個線上MQ集群會同一時間拋出ArrayIndexOutOfBoundsException這個異常，也就是數組越界。查看源碼，除去一些無關緊要的細節大概是這樣子：
public class ConnectionSelector{
private AtomicInteger sets=new AtomicInteger(0);
public void selectConnection(List<Connection> connList){
if(connList==null)｛
return null;
｝
final int size = connList.size();
if (size == 0) {
return null;
}
return connList.get(sets.incrementAndGet() % size);
}
}
private AtomicInteger sets=new AtomicInteger(0);
public void selectConnection(List<Connection> connList){
if(connList==null)｛
return null;
｝
final int size = connList.size();
if (size == 0) {
return null;
}
return connList.get(sets.incrementAndGet() % size);
}
}
很顯然，這裏的本意是實現一個輪詢的連接選擇器，返回一個選中的連接。使用AtomicInteger遞增並對鏈表大小取模，返回結果索引位置的連接。異常拋出的位置就是我代碼中標紅的位置。
顯然，這裏有兩種可能，一種情況下是說在執行那一行代碼的時候，connList的大小縮小了（也就是說連接可能被其他線程移出），那麼導致取模的結果越界。另一種可能是取模的結果本身確實超過了列表範圍。
第一種情況是完全可能的，因為服務器的連接可能隨時斷開或者重連，但是這種情況相對非常少見，因此我們這裏並沒有對這個選擇過程做同步，主要是從性能的角度出發，偶爾的失敗可以接受。很遺憾的是，我被我的思維慣性誤導了，從來沒有懷疑過第二種情況，總是認為是不是真的連接恰巧斷開導致這個異常，但是卻無法解釋這個異常發生後就一直錯誤下去，無法自行恢複。
為什麼說思維慣性誤導呢？這裏的問題其實是負數取模的問題，對一個負數進行取模，結果會是正數還是負數？答案是結果因語言而異。
我很早以前在使用Ruby的時候做過測試，負數取模結果為正數，例如在irb裏嚐試下：
>> -1000%3
=> 2
>> -2001%4
=> 3
=> 2
>> -2001%4
=> 3
這個印象持續至今，在clojure裏結果也是這樣子：
Clojure 1.2.1
user=> (mod -1000 3)
2
user=> (mod -2001 4)
3
user=> (mod -1000 3)
2
user=> (mod -2001 4)
3
可以再試試python:
Python 2.7.1 (r271:86832, Jun 16 2011, 16:59:05)
[GCC 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2335.15.00)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> -10000%3
2
>>> -2001%4
3
[GCC 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2335.15.00)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> -10000%3
2
>>> -2001%4
3
這三種語言的結果完全一致，結果都為正數。這個慣性思維延續到java卻不成立了，可惜我根本沒做測試，讓我們試下：
public static void main(final String[] args) {
System.out.println(-1000 % 3);
System.out.println(-2001 % 4);
}
System.out.println(-1000 % 3);
System.out.println(-2001 % 4);
}
打印結果為：
-1
-1
-1
果然，在java裏負數取模的結果為負數，而不是我習慣性地認為是正數。因此最終的定位到的原因就是sets這個變量遞增超過Integer.MAX_VALUE後越界變成負數了，取模的結果為負數，導致拋出數組越界的異常，這也解釋了為什麼同一個集群都在同一時間出問題，因為這個集群內的機器啟動時間相鄰並且調用這個方法次數相對平均。修正問題很簡單，加個Math.abs就好。
Update:加個abs是不夠的，因為Math.abs的javadoc提醒了：
Note that if the argument is equal to the value of Integer.MIN_VALUE, the most negative representable int value, the result is that same value, which is negative.
也就是說對Integer.MIN_VALUE做abs結果仍然是負數。盡管在這個場景中失敗一次可以接受，但是最好的辦法還是回複中steven提到的抵消符號位的做法：
(sets.incrementAndGet() & 0x7FFFFFFF) % size
這個問題更詳細的討論後來我找到這篇博客，作者討論幾種語言和計算器的這個問題的結果，給出了一些結論。不過我覺的這個結論可能也不是那麼可靠，特別是對c/c++來說，很大程度上應該還是依賴於實現，最可靠的辦法還是強製結果為正。
這個bug的幾個教訓：
1、首先是第一次出現的時候沒有引起足夠重視，重啟解決問題後沒有深究。有句玩笑話：99％的程序問題都可以通過重啟解決。但是事實上問題仍然存在，該發生的終究還會發生。不管你信不信，它就是發生了，這是一個奇跡。
2、注意大腦的思維慣性，經驗主義和教條主義都不可取。最近在讀一本好書《暗時間》，大腦誤導我們的手段可是多種多樣。
3、最後就是這個負數取模的結果因語言而異，不要依賴於特定實現。
文章轉自莊周夢蝶 ，原文發布時間 2011-09-02
最後更新：2017-05-18 20:31:38