2018年12月12日18:44:53
一個ScheduledExecutorService啟動的Java線程無故掛掉引發的思考
案件現場
不久前，在開發改造公司一個端到端監控日志系統的時候，出現了一個bug：有個掃表寫日志的線程無故掛掉。
順藤摸瓜
我看了很久的代碼，都沒有想出來有什么地方有邏輯問題。萬金油的方法是，重啟。當我滿心歡喜地認為重啟是個好方法的時候，問題又重現了。
我有點無奈地看着自己的代碼
本我：堪稱完美的邏輯，還有什么地方是我沒有注意到的嗎？
真我：當然有了，你這個菜鳥，你不知道的地方多着呢。
於是，去找老大問一下問題怎么解決，老大說去生產數據庫上導十萬數據到測試庫，然后在本地debug一下。接着，我就從數據庫里面導出一萬數據開始測試，在eclipse啟動進程，日志寫在本地文件。很快，問題再一次出現。然后斷點，然后找到出問題的地方。出問題的地方如下：
代碼就一行：
String timeStamp = DateUtil.str2Date(receiveTime, DateUtil.YYYYMMDDHH24MISS).getTime() + "000";
這行代碼的意思是，將字符串的接收時間receiveTime格式化，getTime()得到時間戳，因為格式是要微秒，加了三個零。
DateUtil.str2Date方法：（String時間轉化為Date類型，關於時間轉換可以看看本人的String、Date和Timestamp的互轉）
public static Date str2Date(String dateStr, String dateFormat){
if (StringHelper.isEmpty(dateStr)) {
return null;
}
SimpleDateFormat df = new SimpleDateFormat(dateFormat);
try {
return df.parse(dateStr);
} catch (Exception ex) {
return null;
}
}
這個工具類當parse方法拋出異常的時候返回null，看起來是沒有問題的，但是我在轉換之后沒有判斷是否為空即null，然后就變成了null.getTime()，接着就拋了一個很常見的NullPointerException異常。
到這里，看似問題已經解決了，但是問題並沒有那么簡單。
尋根問底
上面說到的在線程中拋出了NullPointerException異常，解決方法是增加一個判斷是否為空的條件就可以了。但是一般來說，有異常的時候，程序沒有捕獲異常，日志里或者debug時控制台會打印異常信息，類似這種：
at com.netease.backend.rds.task.CleanHandleThread.run(CleanHandleThread.java:65)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:317)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:150)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:98)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:204)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
但實際上我debug的時候，並沒有看到打印的異常信息。我是斷點到這一步，發現下一行代碼沒有執行，我就斷定問題是在這里，而且空指針異常一下子就能看出來了。問題來了，為什么沒有打印異常信息呢？我想應該是線程的問題，代碼里啟動這個寫日志的定時任務用的是ScheduledExecutorService：
我Google了一下，發現其實有很多前輩都曾遇到過這個問題。
在這些文章中，我找到了我要的答案。我引用其中的一篇文章從一個java線程掛掉的例子討論分析定位問題基本原則文字作為答案吧。
那么，Java線程掛掉的主要原因是：Any thrown exception or error reaching the executor causes the executor(ScheduledExecutorService) to halt. No more invocations on the Runnable, no more work done. This work stoppage happens silently, you’ll not be informed.
也就是說，如果使用者拋出異常，ScheduledExecutorService 將會停止線程的運行，而且不會報錯，沒有任何提示信息。
這就是在日志中和控制台都沒有看到打印異常信息的原因。
解決方法
寫了一個測試類，有興趣可以研究一下這個bug。
public class ScheduledExecutorServiceThrowExceptionTest {
private static int i = 0;
public static void main(String[] args) {
ScheduledExecutorService exc = Executors.newSingleThreadScheduledExecutor();
exc.scheduleAtFixedRate(new Runnable(){
@Override
public void run() {
i++;
if (i==6) {
throw new RuntimeException();
} else {
System.out.println(i);
}
}
}, 0, 1, TimeUnit.SECONDS);
}
}
測試結果是：
結果顯示，當程序拋出異常的時候，線程就不再運行了，也就是掛了。
解決方法：
- 1、直接加一個
try-catch進行異常捕獲，然后你可以打印你需要的異常信息或者處理異常。
public class ScheduledExecutorServiceThrowExceptionTest1 {
private static int i = 0;
public static void main(String[] args) {
ScheduledExecutorService exc = Executors.newSingleThreadScheduledExecutor();
exc.scheduleAtFixedRate(new Runnable(){
@Override
public void run() {
try {
// doSomething();// TODO：具體業務邏輯
i++;
if (i==6) {
throw new RuntimeException();
} else {
System.out.print(i + " ");
}
} catch (Exception ex) {
System.out.println();
System.out.println("在ScheduledExecutorService中有異常拋出，異常堆棧：" + ex.getStackTrace());
}
}
}, 0, 1, TimeUnit.SECONDS);
}
}
結果是打印了異常信息，且線程沒有被中斷。
1 2 3 4 5
在ScheduledExecutorService中有異常拋出，異常堆棧：[Ljava.lang.StackTraceElement;@1bb53ed8
7 8 9 10 11 12 13
- 2、通過ScheduledFuture對象返回異常信息
public class ScheduledExecutorServiceThrowExceptionTest2 {
private static int i = 0;
public static void main(String[] args) {
ScheduledExecutorService exc = Executors.newSingleThreadScheduledExecutor();
ScheduledFuture<?> handle = exc.scheduleAtFixedRate(new Runnable(){
@Override
public void run() {
i++;
if (i==6) {
throw new RuntimeException();
} else {
System.out.print(i + " ");
}
}
}, 0, 1, TimeUnit.SECONDS);
try {
handle.get();
} catch(Exception ex) {
System.out.println();
System.out.println("在ScheduledExecutorService中有異常拋出，異常堆棧：" + ex.getStackTrace());
}
}
}
這個解決方法打印了異常信息，但是並沒有阻止線程掛掉。
1 2 3 4 5
在ScheduledExecutorService中有異常拋出，異常堆棧：[Ljava.lang.StackTraceElement;@33909752
總結
一個ScheduledExecutorService啟動的Java線程無故掛掉的原因是：如果使用者拋出異常，ScheduledExecutorService 將會停止線程的運行，而且不會報錯，沒有任何提示信息。解決方法是：try-catch將異常信息打印，或者用ScheduledFuture<?>獲取線程運行結果。
寫的bug多，自然經驗就多了，但是要注意總結。
完
2018年12月13日09:08:19