庄周梦蝶

生活、程序、未来
   :: 首页 ::  ::  :: 聚合  :: 管理

找bug记(1)

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

    转载请注明出处 http://www.blogjava.net/killme2008/archive/2011/07/10/354062.html

    上周在线上系统发现了两个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的误用引起的。SimpleDateFormatjavadoc中有这么句话:
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的查找经历,也是比较有趣,可以看到一些工具的使用。


评论

# re: 找bug记(1)  回复  更多评论   

2011-07-11 09:56 by fuyou001
程序员不正确的优化,并期待下篇

# re: 找bug记(1)  回复  更多评论   

2011-07-11 10:38 by hz_hz
你找的这台机器是急群中的产品线上的server吗

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

# re: 找bug记(1)  回复  更多评论   

2011-07-11 10:43 by hz_hz
但是有时开发server又很难重现 产品线上的问题 这个时候就比较麻烦
解决问题得选在 空闲时间

# re: 找bug记(1)  回复  更多评论   

2011-07-11 15:00 by xiekz
内容很好,期待下一篇文章

# re: 找bug记(1)[未登录]  回复  更多评论   

2011-07-11 18:04 by xiaoyu
感觉方法1的测试结果很奇怪, 估计是不是产生了大量的GC?

# re: 找bug记(1)  回复  更多评论   

2011-07-11 18:10 by dennis
@hz_hz

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


@xiaoyu

这里gc有影响,new对象的开销也有影响。如果你用jstat观察测试程序的gc情况就能发现。

# re: 找bug记(1)  回复  更多评论   

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

# re: 找bug记(1)[未登录]  回复  更多评论   

2011-07-12 12:58 by steven
(2)在server模式下,最好都设置-XX:-OmitStackTraceInFastThrow

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

# re: 找bug记(1)  回复  更多评论   

2011-07-12 15:40 by MrKiller
不错的文章,很有启发。

# re: 找bug记(1)  回复  更多评论   

2011-07-12 20:59 by dennis
@imlyj

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

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


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

# re: 找bug记(1)  回复  更多评论   

2011-07-12 21:00 by dennis
@steven
有数据证明这一点吗?一个应用如果经常性地频繁抛异常,我觉的只有两种可能:
(1)应用本身有问题,写的不够健壮
(2)将异常当成控制流使用。

# re: 找bug记(1)  回复  更多评论   

2011-07-16 00:00 by imlyj
  谢谢@dennis给予我的解答。继续我的疑问。
javac和java命令我在借助IDE的时候就基本不用了,呵呵。至于java -Xmx512m HelloWorld,是编译HelloWorld这个应用,并且调置JVM参数是吧,那这次编译完,下次重新JVM,参数还要重新指定吗?这个有点疑问。我理解是是不是下次重启JVM时,还得再调一下java -Xmx512m HelloWorld吧,那启不是很烦!!
还有你eclipse的调优我记住了。我们在生产环境中,即在centos中,我们只是直接调用tomcat.sh命令启动应用,顺便jvm被起来,这个时候,我要调整参数比如你说的-XX:-OmitStackTraceInFastThrow。应该怎么弄呢。别笑话我。我真没接触过这个,还请麻烦一下。
  我问这么细,一个我是真不清楚,二个网上没搜到,最重要是上上星期去sohu面试时,PM问我调优啥的。我被鄙视了。所以既然你讲了。我就多问一下了。呵呵!!

# re: 找bug记(1)[未登录]  回复  更多评论   

2011-07-20 09:21 by steven
@dennis
虽然我不能给你确切的数据,但是从理论上来说这是毋庸置疑的,否则jdk不会多搞出这个参数来做优化,再说出现这个问题一定是程序有问题,所以我们正确的做法应该是避免这种不合适的使用就可以了。。。至于你说的异常当作控制流的问题我倒觉得应该尽量避免,实在没有办法抛出一个stack比较浅的exception就可以了。。。

# re: 找bug记(1)  回复  更多评论   

2011-07-20 09:46 by dennis
@steven
恩,我相信对性能是有影响的。这里是一个权衡问题,我是倾向于配置这个参数来发现任何异常隐患,因为异常通常对应一个问题,而性能通常是最后一个考虑因素。

# re: 找bug记(1)  回复  更多评论   

2011-07-21 12:26 by imlyj
@dennis

麻烦回答我的问题吧。

# re: 找bug记(1)  回复  更多评论   

2011-07-24 11:24 by jameswxx
我看到很多同事确实有些小地方没有注意到:
SimpleDateFormat不是线程安全的,被很多人误用了。
打日志是吃掉了异常堆栈。

只有注册用户登录后才能发表评论。


网站导航: