175
找bug記（1）
|
轉載請注明出處 https://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的誤用引起的。SimpleDateFormat的javadoc中有這麼句話：
Date formats are not synchronized. It is recommended to create separate format instances for each thread.
但是很悲劇的是這句話是放在整個doc的最後麵，在我看來，這句話應該放在最前麵才對。簡單來說就是SimpleDateFormat不是線程安全的，你要麼每次都new一個來用，要麼做加鎖來同步使用。If multiple threads access a format concurrently, it must be synchronized externally. 出問題的代碼就是由於工程師認為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最慢，方法3最快，但是就算是最慢的方法1也可以達到每秒鍾200 20萬次的調用量，很少有係統能達到這個量級。這個點很難成為你係統的瓶頸所在。從我的角度出發，我會建議你用方法1或者方法2，如果你追求那麼一點性能提升的話，可以考慮用方法3，也就是用ThreadLocal做緩存。 總結下本文找bug經曆想表達的幾點想法： （1）正確地打印錯誤日誌 （2）在server模式下，最好都設置-XX:-OmitStackTraceInFastThrow （3）使用類或者方法的時候，最好能詳細閱讀下javadoc，很多問題都能找到答案 （4）使用SimpleDateFormat的時候要注意線程安全性，要麼每次new，要麼做同步，兩者的性能有差距，但是這個差距很難成為你的性能瓶頸。 下篇文章我再分享另一個bug的查找經曆，也是比較有趣，可以看到一些工具的使用 文章轉自莊周夢蝶 ，原文發布時間 2011-07-10
|
最後更新：2017-05-18 20:31:29