找bug记(1)

标签: 未分类 | 发表时间:2011-07-11 11:27 | 作者:boyan peigen
出处:http://rdc.taobao.com/team/jm

转载请注明出处 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的查找经历,也是比较有趣,可以看到一些工具的使用。

相关 [bug] 推荐:

找bug记(1)

- BTK 4eVeR - BlogJava-庄周梦蝶
    转载请注明出处 http://www.blogjava.net/killme2008/archive/2011/07/10/354062.html.     上周在线上系统发现了两个bug,值得记录下查找的过程和原因. 以后如果还有查找bug比较有价值的经历,我也会继续分享.     第一个bug的起始,是在线上日志发现一个频繁打印的异常——java.lang.ArrayIndexOutOfBoundsException.

找bug记(2)

- gengmao - BlogJava-庄周梦蝶
    这篇blog迟到了很久,本来是想写另一个跟网络相关bug的查找过程,偷偷懒,写下最近印象比较深刻的bug. 这个bug是我的同事水寒最终定位到的.     前几个月同事报告称有一个线上MQ集群会同一时间抛出ArrayIndexOutOfBoundsException这个异常,也就是数组越界.

Scrum中管理bug

- - CSDN博客研发管理推荐文章
如果bug来自于正在开发的sprint. 会在task阶段就被QA/Scrum Master/Product Owner标记为有bug,并且Story不能被置为done状态,这个很容易解决. 如果bug来自于已经结束的sprint,那么怎么办呢. 理想状态下是将bug放到backlogs中,然后由product owner调整其优先级,并决定放在后面的哪一个sprint中修复.

Fix Bug的五个阶段

- Sirius - 酷壳 - CoolShell.cn
下面的文章和《各种流行的编程方式》有异曲同工,请你不要理解错了. 一个非常严重和困难的bug,能够成就一个饱经沧桑深受压力的有经验的专业程序员的职业生涯. 经受这种考验的创伤程度,相当你受到了一次严重的身体伤害,离婚,或是家庭成为的离世. 研究人员在研究了计算机编程心理学后,得出了一个程序员们在解决一个困难的bug时的心路里程.

mysql order by和limit共用bug

- - 数据库 - ITeye博客
 在mysql下执行没有问题,可以得到预期结果. 但是用jdbc执行的时候就得不到预期结果了. 官网地址:http://bugs.mysql.com/bug.php?id=32933. 以下转载:http://bbs.chinaunix.net/thread-1276235-1-1.html. 我想从一个表中检索所有标题含有“中国”的数据,将它们按id排序,取前5条,所以我写了以下语句.

Java 7被发现含有严重bug

- Jingzhi - Solidot
甲骨文在Java 7中作出某些改变时,可能没很好的进行测试;但在发现严重bug后,它仍按时间表推出了Java 7. Java 7和Java 6都存在相同的bug,不同之处是前者默认启用,而后者没有. HotSpot Loop优化中的bug可能会导致JVM崩溃,或者是执行错误. Bug影响了多个Apache项目,包括Apache Lucene Core和Apache Solr.

Glibc改变导致bug出现

- allengaller - Solidot
在网上通过Flash插件听MP3遭遇破音的Linux用户也许需要去看下Fedora bugzilla,但这个bug的根源颇有些周折: Glibc开发者改动了memcpy()函数实现,它在理论上只是对目前的处理器进行优化,但不幸的是改动暴露了代码中的bug,开发者忽略了传递给memcpy()函数的源和目标数组不能重叠的规定.

首个计算机Bug的由来

- bill - cnBeta.COM
“Bug”一词,是指“故障”、“缺陷”. 了解软件开发的朋友都非常熟悉,程序员和测试人员更不用说,在工作中会常遇到. 9月9日下午在微博上看到@新浪科技发了一条微博消息:.