我们有一个 ThreadPoolExecutor-back 任务执行模块。有些任务显然在应用程序代码中完成了,但是工作代码以某种方式跳过了所有的 try/catch/finally 并继续执行下一个任务,导致前一个任务错过了重要的状态报告代码。
就像在这个例子中一样,257832:5 被线程 8 拾取,但这个线程最终只是启动了另一个任务。
2012-07-11 15:53:39,389 信息 [pool-1-thread-6]:任务 (258861:5):开始。 2012-07-11 15:53:39,389 信息 [pool-1-thread-6]: 运行的任务 ### 由应用程序逻辑记录 2012-07-11 15:54:18,186 信息 [pool-1-thread-6]:任务 (258868:5):开始。###突然捡到一个! 2012-07-11 15:54:18,186 信息 [pool-1-thread-6]: 运行的任务 ### 由应用程序逻辑记录 2012-07-11 15:54:18,445 信息 [pool-1-thread-6]:任务 (258868:5):从 Task.doWork 返回。 2012-07-11 15:54:18,446 信息 [pool-1-thread-6]:任务 (258868:5):完成。 2012-07-11 15:54:18,487 信息 [pool-1-thread-6]:任务 (258868:5):通知状态结果:200。 2012-07-11 15:54:18,487 信息 [pool-1-thread-6]:任务 (258868:5):已完成
ThreadPoolExecutor 的 Runnable 看起来不错。看起来像
public void run() {
log.info(String.format("Task (%s:%s) : Starting.", wfId, taskId));
try {
Object result = task.doWork(...); // call the application codes
log.info(String.format("Task (%s:%s) : returned from Task.doWork.", wfId, taskId));
status = "DONE";
} catch (Throwable t) {
log.error("Error executing task: " + taskId + " - " + className);
} finally {
log.info(String.format("Task (%s:%s) : finalizing.", wfId, taskId));
// notify status to a server
log.info(String.format("Task (%s:%s) : Finished", wfId, taskId));
}
}
// the task framework looks like
// Use a queue size larger than numThreads, since the ThreadPoolExecutor#getActiveCount() call only returns an approximate count
this.executor = new ThreadPoolExecutor(numThreads, numThreads, 60, TimeUnit.SECONDS, new ArrayBlockingQueue<Runnable>(numThreads * 2));
executor.execute(new TaskRunnable(...));
笔记:
- 我们捕获了最终的 Throwable 但两个任务之间没有记录异常
- 没有迹象表明 exit() 被调用或程序重新启动
- 第一个跳过所有日志行,无论是在调用应用程序代码之后的那个还是在 catch 和 finally 块中的那个,并跳过状态报告代码
- 这只会以低概率随机发生;但是由于执行的任务量很大,还是让我们很头疼。
就好像线程池执行器只是神奇地驱逐了正在运行的可运行对象(否则它需要一个 InterruptedException,它会被捕获为 Throwable;Java 线程不会以非合作方式停止,除非在关闭/退出期间)并跳过所有块。我检查了 ThreeadPoolExecutor javadoc,没有什么会导致这样的事件发生。
可能发生了什么?