轉載請注明出處
http://www.tkk7.com/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的誤用引起的。
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的查找經歷，也是比較有趣，可以看到一些工具的使用。