淘宝牛人找bug记（1）

为什么80%的码农都做不了架构师？>>>   

上周在线上系统发现了两个bug，值得记录下查找的过程和原因。以后如果还有查找bug比较有价值的经历，我也会继续分享。
    第一个bug的起始，是在线上日志发现一个频繁打印的异常——java.lang.ArrayIndexOutOfBoundsException。但是却没有堆栈，只有一行一行的ArrayIndexOutOfBoundsException。没有堆栈，不知道异常是从什么地方抛出来的，也就不能找到问题的根源，更谈不上解决。题外，工程师在用log4j记录错误异常的时候，我看到很多人这样用（假设e是异常对象）：

log.error( " 发生错误: " + e);

或者：

log.error( " 发生错误: " + e.getMessage());

    这样的写法是不对，只记录了异常的信息，而没有将堆栈输出到日志，正确的写法是利用error的重载方法：

log.error( " xxx发生错误 " ,e);

    这样才能在日志中完整地输出异常堆栈来。如何写好日志是另一个话题，这里不展开。继续我们的找bug经历。刚才提到，我们线上日志一直出现一行错误信息ArrayIndexOutOfBoundsException却没有堆栈，是我们没有正确地写日志吗？检查代码不是的，这个问题其实是跟JDK5引入的一个新特性有关，对于一些频繁抛出的异常，JDK为了性能会做一个优化，在JIT重新编译后会抛出没有堆栈的异常。在使用server模式的时候，这个优化是开启的，我们的服务器跑在server模式下并且jdk版本是6，因此在频繁抛出ArrayIndexOutOfBoundsException异常一段时间后优化开始起作用，只抛出没有堆栈的异常信息了。

    那么怎么解决这个问题呢？因为这个优化是在JIT重新编译后才起作用，因此一开始抛出异常的时候还是有堆栈的，所以可以查看较旧的日志，寻找有完整堆栈的异常信息。但是由于我们的日志太大，会定期删除，我们的服务器也启动了很长时间，因此查找日志不是很靠谱的方法。
    另一个解决办法是暂时禁用这个优化，强制要求每次都要抛出有堆栈的异常。幸好JDK提供了选项来关闭这个优化，配置JVM参数

- XX: - OmitStackTraceInFastThrow

    就可以禁止这个优化（注意选项中的减号，加号是启用）。

    我们找了台机器，配置了这个参数并重启一下。过了一会就找到问题所在，堆栈类似这样

Caused by: java.lang.ArrayIndexOutOfBoundsException:  - 1831238
    at sun.util.calendar.BaseCalendar.getCalendarDateFromFixedDate(BaseCalendar.java: 436 )
    at java.util.GregorianCalendar.computeFields(GregorianCalendar.java: 2081 )
    at java.util.GregorianCalendar.computeFields(GregorianCalendar.java: 1996 )
    at java.util.Calendar.setTimeInMillis(Calendar.java: 1109 )
    at java.util.Calendar.setTime(Calendar.java: 1075 )
    at java.text.SimpleDateFormat.format(SimpleDateFormat.java: 876 )
    at java.text.SimpleDateFormat.format(SimpleDateFormat.java: 869 )
    at java.text.DateFormat.format(DateFormat.java: 316 )

    读者肯定猜到了，这个问题是由于SimpleDateFormat的误用引起的。 SimpleDateFormat的 javadoc中有这么句话：

Date formats are not  synchronized . It is recommended to create separate format instances  for  each thread. 
If multiple threads access a format concurrently, it must be  synchronized  externally. 

    但是很悲剧的是这句话是放在整个doc的最后面，在我看来，这句话应该放在最前面才对。简单来说就是SimpleDateFormat不是线程安全的，你要么每次都new一个来用，要么做加锁来同步使用。

    出问题的代码就是由于工程师认为SimpleDateFormat的创建代价很高，然后搞了个map做缓存，所有线程共用这个instance做format，同时没有做同步。悲剧就诞生了。
    这里就引出我想提到的第二点问题，在使用一个类或者方法的时候 ，最好能详细地看下该类的javadoc，JDK的javadoc是做的非常好的，javadoc除了做说明之外，通常还会给示例，并且会点出一些关键问题，如线程安全性和平台移植性。

    最后，我将做个测试，到底在使用SimpleDateFormat怎么做才是最好的方式？假设我们要实现一个formatDate方法将日期格式化成"yyyy-MM-dd"的格式。
    第一个方法是每次使用都创建一个instance，并调用format方法：

    public   static  String formatDate1(Date date) {
        SimpleDateFormat format  =   new  SimpleDateFormat( " yyyy-MM-dd " );
         return  format.format(date);
    }

    第二个方法是只创建一个instance，但是在调用方法的时候做同步：

    private   static   final  SimpleDateFormat formatter  =   new  SimpleDateFormat( " yyyy-MM-dd " );

     public   static   synchronized  String formatDate2(Date date) {
         return  formatter.format(date);
    }

    第三个方法比较特殊，我们为每个线程都缓存一个instance，存放在ThreadLocal里，使用的时候从ThreadLocal里取就可以了:

    private   static  ThreadLocal < SimpleDateFormat >  formatCache  =   new  ThreadLocal < SimpleDateFormat > () {

        @Override
         protected  SimpleDateFormat initialValue() {
             return   new  SimpleDateFormat( " yyyy-MM-dd " );
        }

    };

     public   static  String formatDate3(Date date) {
        SimpleDateFormat format  =  formatCache.get();
         return  format.format(date);
    }

    然后我们测试下三个方法并发调用下的性能并做一个比较，并发100个线程循环调用1000万次，记录耗时。我们设置了JVM参数：

- Xmx512m  - XX:CompileThreshold = 10000

    设置堆最大为512M，设置当一个方法被调用1万次的时候就被JIT编译。测试的结果如下：

	第1次测试	第2次测试	第3次测试
formatDate1	50545	49365	53532
formatDate2	10895	10761	10673
formatDate3	10386	9919	9527

(单位：毫秒）
    
    从结果来看，方法1最慢，方法3最快，但是就算是最慢的方法1也可以达到每秒钟 200  20万次的调用量，很少有系统能达到这个量级。这个点很难成为你系统的瓶颈所在。从我的角度出发，我会建议你用方法1或者方法2，如果你追求那么一点性能提升的话，可以考虑用方法3，也就是用ThreadLocal做缓存。

    总结下本文找bug经历想表达的几点想法：
（1）正确地打印错误日志
（2）在server模式下，最好都设置 - XX: - OmitStackTraceInFastThrow
（3）使用类或者方法的时候，最好能详细阅读下javadoc，很多问题都能找到答案
（4）使用SimpleDateFormat的时候要注意线程安全性，要么每次new，要么做同步，两者的性能有差距，但是这个差距很难成为你的性能瓶颈。

    下篇文章我再分享另一个bug的查找经历，也是比较有趣，可以看到一些工具的使用。

posted on 2011-07-10 23:29 dennis 阅读(1578) 评论(11)  编辑  收藏 所属分类: java

评论

# re: 找bug记（1） 2011-07-11 09:56 fuyou001

程序员不正确的优化，并期待下篇  回复  更多评论   

# re: 找bug记（1） 2011-07-11 10:38 hz_hz

你找的这台机器是急群中的产品线上的server吗

如果慎重起见或者不允许产品线机器随便重启 恐怕只能在开发机上做这个测试了  回复  更多评论   

# re: 找bug记（1） 2011-07-11 10:43 hz_hz

但是有时开发server又很难重现 产品线上的问题 这个时候就比较麻烦
解决问题得选在 空闲时间  回复  更多评论   

# re: 找bug记（1） 2011-07-11 15:00 xiekz

内容很好，期待下一篇文章  回复  更多评论   

# re: 找bug记（1）[未登录] 2011-07-11 18:04 xiaoyu

感觉方法1的测试结果很奇怪， 估计是不是产生了大量的GC？  回复  更多评论   

# re: 找bug记（1） 2011-07-11 18:10 dennis

@hz_hz

是线上机器，我们都是集群部署的应用。


@xiaoyu

这里gc有影响，new对象的开销也有影响。如果你用jstat观察测试程序的gc情况就能发现。  回复  更多评论   

# re: 找bug记（1） 2011-07-12 11:39 imlyj

不好意思的问题一句：我们用的是tomcat，所以我就知道设置内存大小可以在catalina.sh里。不知道您设置jvm参数在哪设置的呀。我网上找一圈也没找到答案。网上全告诉你怎么调。就没告诉你在哪调。你别见笑。还有你这篇文章看完我有疑问：出现没有堆栈的信息，你怎么就知道是“JDK5引入的一个新特性有关".而且要调整-XX:-OmitStackTraceInFastThrow参数。我总觉得你没有把这个来龙去脉讲清楚。感觉解决问题的时候全是跳跃性的。能否给解答一下？我相信任何的问题及其解决方法，肯定有其来龙去脉。你说呢？  回复  更多评论   

# re: 找bug记（1）[未登录] 2011-07-12 12:58 steven

（2）在server模式下，最好都设置-XX:-OmitStackTraceInFastThrow 

这个最好不要这么做，因为这个会比较影响性能，为了定位问题，重启一下JVM，这个异常信息会被完整打印出来，也很方便定位问题。  回复  更多评论   

# re: 找bug记（1） 2011-07-12 15:40 MrKiller

不错的文章，很有启发。  回复  更多评论   

# re: 找bug记（1） 2011-07-12 20:59 dennis

@imlyj

这是我没有讲清楚。我们过去遇到过这个问题，在发现日志记录没有问题的时候，自然而然就想到这一点。如果第一次遇到这个问题，我的解决办法可能是使用搜索引擎来查找问题。

怎么设置jvm参数？java -Xmx512m HelloWorld即可。如果你没用过javac和java命令，那很奇怪。在eclipse里可以在run里的vm参数设置。


至于跳跃性，在解决一个没有思路的问题的时候，需要你发散性地思维，考虑各种可能，充分发挥自己的经验和知识。

转载于:https://my.oschina.net/opleo/blog/28268