找bug记(2)

发表于 2011-09-10   |   分类于  未分类    |  

    这篇blog迟到了很久，本来是想写另一个跟网络相关bug的查找过程，偷偷懒，写下最近印象比较深刻的bug。这个bug是我的同事水寒最终定位到的。

    前几个月同事报告称有一个线上MQ集群会同一时间抛出ArrayIndexOutOfBoundsException这个异常，也就是数组越界。查看源码，除去一些无关紧要的细节大概是这样子：

<!–

Code highlighting produced by Actipro CodeHighlighter (freeware)

http://www.CodeHighlighter.com/

–> 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);

}

   }

    很显然，这里的本意是实现一个轮询的连接选择器，返回一个选中的连接。使用AtomicInteger递增并对链表大小取模，返回结果索引位置的连接。异常抛出的位置就是我代码中标红的位置。

    显然，这里有两种可能，一种情况下是说在执行那一行代码的时候，connList的大小缩小了（也就是说连接可能被其他线程移出），那么导致取模的结果越界。另一种可能是取模的结果本身确实超过了列表范围。

    第一种情况是完全可能的，因为服务器的连接可能随时断开或者重连，但是这种情况相对非常少见，因此我们这里并没有对这个选择过程做同步，主要是从性能的角度出发，偶尔的失败可以接受。很遗憾的是，我被我的思维惯性误导了，从来没有怀疑过第二种情况，总是认为是不是真的连接恰巧断开导致这个异常，但是却无法解释这个异常发生后就一直错误下去，无法自行恢复。

    为什么说思维惯性误导呢？这里的问题其实是负数取模的问题，对一个负数进行取模，结果会是正数还是负数？答案是结果因语言而异。

    我很早以前在使用Ruby的时候做过测试，负数取模结果为正数，例如在irb里尝试下：

<!–

Code highlighting produced by Actipro CodeHighlighter (freeware)

http://www.CodeHighlighter.com/

–> >> -1000%3

=> 2

>> -2001%4

=> 3

    这个印象持续至今，在clojure里结果也是这样子：

<!–

Code highlighting produced by Actipro CodeHighlighter (freeware)

http://www.CodeHighlighter.com/

–> Clojure 1.2.1

user=> (mod -1000 3)

2

user=> (mod -2001 4)

3

    可以再试试python:

<!–

Code highlighting produced by Actipro CodeHighlighter (freeware)

http://www.CodeHighlighter.com/

–> 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

    这三种语言的结果完全一致，结果都为正数。这个惯性思维延续到java却不成立了，可惜我根本没做测试，让我们试下：

<!–

Code highlighting produced by Actipro CodeHighlighter (freeware)

http://www.CodeHighlighter.com/

–>     public   static   void  main( final  String[] args) {

        System.out.println(-1000 % 3);

        System.out.println(-2001 % 4);

    }

打印结果为：

<!–

Code highlighting produced by Actipro CodeHighlighter (freeware)

http://www.CodeHighlighter.com/

–> -1

-1

    果然，在java里负数取模的结果为负数，而不是我习惯性地认为是正数。因此最终的定位到的原因就是sets这个变量递增超过Integer.MAX_VALUE后越界变成负数了，取模的结果为负数，导致抛出数组越界的异常，这也解释了为什么同一个集群都在同一时间出问题，因为这个集群内的机器启动时间相邻并且调用这个方法次数相对平均。修正问题很简单，加个Math.abs就好。

    这个问题更详细的讨论后来我找到 这篇博客 ，作者讨论几种语言和计算器的这个问题的结果，给出了一些结论。不过我觉的这个结论可能也不是那么可靠，特别是对c/c++来说，很大程度上应该还是依赖于实现，最可靠的办法还是强制结果为正。

    这个bug的几个教训：

1、首先是第一次出现的时候没有引起足够重视，重启解决问题后没有深究。有句玩笑话：99％的程序问题都可以通过重启解决。但是事实上问题仍然存在，该发生的终究还会发生。不管你信不信，它就是发生了，这是一个奇迹。

2、注意大脑的思维惯性，经验主义和教条主义都不可取。最近在读一本好书《 暗时间 》，大脑误导我们的手段可是多种多样。

3、最后就是这个负数取模的结果因语言而异，不要依赖于特定实现。