京公网安备11010502063487号返回 Callable 和 DeferredResult 到底发生了什么?拦截器为什么被调用两次?超时设成 100 毫秒为什么等了将近一秒?超时之后慢任务还会继续跑吗?异步到底省了什么?这篇在 Spring Boot 4.0.8 的 Spring MVC 7.0.9 上打印线程名和派发类型逐个验证。
GET /sync → 200 sync-done (363 ms)
拦截器 preHandle [REQUEST] /sync 在 http-nio-9601-exec-2
/sync 方法在 http-nio-9601-exec-2
拦截器 postHandle [REQUEST]
拦截器 afterCompletion [REQUEST]
GET /callable → 200 callable-done (330 ms)
拦截器 preHandle [REQUEST] /callable 在 http-nio-9601-exec-3
/callable 控制器方法在 http-nio-9601-exec-3,返回 Callable
拦截器 afterConcurrentHandlingStarted(原线程释放前)
/callable 的 Callable 在 task-1 执行
拦截器 preHandle [ASYNC] /callable 在 http-nio-9601-exec-4
拦截器 postHandle [ASYNC]
拦截器 afterCompletion [ASYNC]原线程释放,Callable 在 task 线程跑,完成后以 ASYNC 重新派发。
请求 /deferred 发出 0.5 秒后,客户端还在等响应: True
/deferred 最终 → 200 deferred-ok (总耗时 521 ms)
拦截器 preHandle [REQUEST] /deferred 在 http-nio-9602-exec-1
/deferred 控制器方法在 http-nio-9602-exec-1,返回 DeferredResult(id=d1)
拦截器 afterConcurrentHandlingStarted(原线程释放前)
/complete 在 http-nio-9602-exec-3 完成 DeferredResult(d1) → true
拦截器 preHandle [ASYNC] /deferred 在 http-nio-9602-exec-4
拦截器 postHandle [ASYNC]
拦截器 afterCompletion [ASYNC]
GET /from-timer → 200 from-timer-done (213 ms)
拦截器 preHandle [REQUEST] /from-timer 在 http-nio-9602-exec-5
/from-timer 控制器方法在 http-nio-9602-exec-5
拦截器 afterConcurrentHandlingStarted(原线程释放前)
my-timer 线程里 setResult
拦截器 preHandle [ASYNC] /from-timer 在 http-nio-9602-exec-6
拦截器 postHandle [ASYNC]
拦截器 afterCompletion [ASYNC]由任意线程、任意请求完成,谁来完成都可以。
GET /deferred-timeout?ms=500 → 200 timeout-fallback (1035 ms)
onTimeout 回调在 http-nio-9603-exec-3
onCompletion 回调在 http-nio-9603-exec-3
GET /deferred-timeout-default → 500 [AsyncRequestTimeoutException] null (829 ms)
onTimeout 回调在 http-nio-9603-exec-5
@ExceptionHandler 收到 AsyncRequestTimeoutException 在 http-nio-9603-exec-5
GET /callable-timeout → 500 [AsyncRequestTimeoutException] null (1828 ms)
慢 Callable 的 sleep 被中断了(InterruptedException),线程 task-1
@ExceptionHandler 收到 AsyncRequestTimeoutException 在 http-nio-9603-exec-7
(等 3.2 秒再看慢 Callable 的下场)
慢 Callable 的 sleep 被中断了(InterruptedException),线程 task-1有兜底值就返回兜底值,没有就抛 AsyncRequestTimeoutException;超时的 Callable 被中断。
DeferredResult 超时 100 ms,6 次(每次开始前错开一点时间)实际等了(ms):[984, 864, 687, 519, 333, 132] DeferredResult 超时 300 ms,6 次(每次开始前错开一点时间)实际等了(ms):[1009, 862, 676, 526, 327, 1158] DeferredResult 超时 700 ms,6 次(每次开始前错开一点时间)实际等了(ms):[997, 862, 1688, 1524, 1337, 1149]
实际等待时间像是对齐到 1 秒的节拍,亚秒级的超时靠不住。
GET /callable-ex → 500 [IllegalStateException] callable 里抛的 (46 ms)
拦截器 preHandle [REQUEST] /callable-ex 在 http-nio-9605-exec-2
拦截器 afterConcurrentHandlingStarted(原线程释放前)
拦截器 preHandle [ASYNC] /callable-ex 在 http-nio-9605-exec-3
@ExceptionHandler 收到 IllegalStateException 在 http-nio-9605-exec-3
拦截器 afterCompletion [ASYNC]
GET /deferred-ex → 500 [IllegalArgumentException] setErrorResult 设的 (115 ms)
拦截器 preHandle [REQUEST] /deferred-ex 在 http-nio-9605-exec-4
拦截器 afterConcurrentHandlingStarted(原线程释放前)
拦截器 preHandle [ASYNC] /deferred-ex 在 http-nio-9605-exec-5
@ExceptionHandler 收到 IllegalArgumentException 在 http-nio-9605-exec-5
拦截器 afterCompletion [ASYNC]异步里的异常在重新派发之后走异常处理器。
10 个并发 /sync(每个 300ms):总耗时 1.58 s,状态码都是 200:True;期间另一个 /inflight 等了 1161 ms Callable 实际执行在 8 个不同的线程上:['task-1', 'task-2', 'task-3', 'task-4', 'task-5', 'task-6', 'task-7', 'task-8'] 10 个并发 /block-sleep(Callable,每个 300ms):总耗时 0.64 s,状态码都是 200:True;期间另一个 /inflight 等了 1 ms
异步把等待从 Tomcat 线程挪到另一个池子,池子的大小同样会成为瓶颈。