springboot异步mvc使用threadlocal的正确姿势

log

2017-02-08 23:13:25.902  INFO 1516 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Request received,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:13:25.904  INFO 1516 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Servlet thread released,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:13:25.906  INFO 1516 --- [nio-8080-exec-1] c.p.config.TraceAsyncRequestInterceptor  : beforeConcurrentHandling get from mdc:null,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:13:25.909  INFO 1516 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : preProcess get from mdc:null,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:13:30.914  INFO 1516 --- [      MvcAsync1] com.xixicat.service.TaskService       : task service get from mdc:localhost get by mdc,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:13:30.914  INFO 1516 --- [      MvcAsync1] com.xixicat.service.TaskService       : Slow task executed,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:13:30.914  INFO 1516 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : postProcess CALLED,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:13:30.937  INFO 1516 --- [nio-8080-exec-2] c.p.config.TraceAsyncRequestInterceptor  : afterCompletion CALLED,thread:Thread[http-nio-8080-exec-2,5,main]

接收请求与返回的响应不是同一个线程
beforeConcurrentHandling是在接收线程里头执行
preProcess是在异步线程里执行
postProcess是在异步线程里执行
afterCompletion是在响应线程

或者

2017-02-08 23:13:57.555  INFO 1516 --- [nio-8080-exec-3] c.p.controller.AsyncCallableController   : Request received,thread:Thread[http-nio-8080-exec-3,5,main]
2017-02-08 23:13:57.555  INFO 1516 --- [nio-8080-exec-3] c.p.controller.AsyncCallableController   : Servlet thread released,thread:Thread[http-nio-8080-exec-3,5,main]
2017-02-08 23:13:57.555  INFO 1516 --- [nio-8080-exec-3] c.p.config.TraceAsyncRequestInterceptor  : beforeConcurrentHandling get from mdc:null,thread:Thread[http-nio-8080-exec-3,5,main]
2017-02-08 23:13:57.556  INFO 1516 --- [      MvcAsync2] c.p.config.TraceAsyncRequestInterceptor  : preProcess get from mdc:null,thread:Thread[MvcAsync2,5,main]
2017-02-08 23:14:02.559  INFO 1516 --- [      MvcAsync2] com.xixicat.service.TaskService       : task service get from mdc:localhost get by mdc,thread:Thread[MvcAsync2,5,main]
2017-02-08 23:14:02.560  INFO 1516 --- [      MvcAsync2] com.xixicat.service.TaskService       : Slow task executed,thread:Thread[MvcAsync2,5,main]
2017-02-08 23:14:02.560  INFO 1516 --- [      MvcAsync2] c.p.config.TraceAsyncRequestInterceptor  : postProcess CALLED,thread:Thread[MvcAsync2,5,main]
2017-02-08 23:14:02.566  INFO 1516 --- [nio-8080-exec-4] c.p.config.TraceAsyncRequestInterceptor  : afterCompletion CALLED,thread:Thread[http-nio-8080-exec-4,5,main]

3s超时,处理sleep 5s

2017-02-08 23:15:26.660  INFO 1530 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Request received,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:15:26.662  INFO 1530 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Servlet thread released,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:15:26.664  INFO 1530 --- [nio-8080-exec-1] c.p.config.TraceAsyncRequestInterceptor  : beforeConcurrentHandling get from mdc:null,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:15:26.667  INFO 1530 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : preProcess get from mdc:null,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:15:30.076  INFO 1530 --- [nio-8080-exec-2] c.p.config.TraceAsyncRequestInterceptor  : handleTimeout CALLED,thread:Thread[http-nio-8080-exec-2,5,main]
2017-02-08 23:15:30.089  INFO 1530 --- [nio-8080-exec-2] c.p.config.TraceAsyncRequestInterceptor  : afterCompletion CALLED,thread:Thread[http-nio-8080-exec-2,5,main]
2017-02-08 23:15:31.668  INFO 1530 --- [      MvcAsync1] com.xixicat.service.TaskService       : task service get from mdc:localhost get by mdc,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:15:31.668  INFO 1530 --- [      MvcAsync1] com.xixicat.service.TaskService       : Slow task executed,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:15:31.668  INFO 1530 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : postProcess CALLED,thread:Thread[MvcAsync1,5,main]

handleTimeout是在响应线程里头执行
afterCompletion是在响应线程
3秒timeout完,返回请求线程执行handleTimeout,然后执行afterCompletion
5秒时,异步线程执行完,执行postProcess

没有超时,但task抛出异常情况

2017-02-08 23:27:31.164  INFO 1551 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Request received,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:27:31.166  INFO 1551 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Servlet thread released,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:27:31.168  INFO 1551 --- [nio-8080-exec-1] c.p.config.TraceAsyncRequestInterceptor  : beforeConcurrentHandling get from mdc:null,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:27:31.171  INFO 1551 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : preProcess get from mdc:null,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:27:36.174  INFO 1551 --- [      MvcAsync1] com.xixicat.service.TaskService       : task service get from mdc:localhost get by mdc,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:27:36.174  INFO 1551 --- [      MvcAsync1] com.xixicat.service.TaskService       : Slow task executed,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:27:36.174  INFO 1551 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : postProcess CALLED,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:27:36.196 ERROR 1551 --- [nio-8080-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet dispatcherServlet threw exception
java.lang.RuntimeException: test
    at com.xixicat.service.TaskService.execute(TaskService.java:17) ~[classes/:na]
    at org.springframework.web.context.request.async.WebAsyncManager$4.run(WebAsyncManager.java:316) ~[spring-web-4.3.5.RELEASE.jar:4.3.5.RELEASE]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_71]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_71]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_71]
2017-02-08 23:27:36.197 ERROR 1551 --- [nio-8080-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.RuntimeException: test] with root cause
java.lang.RuntimeException: test
    at com.xixicat.service.TaskService.execute(TaskService.java:17) ~[classes/:na]
    at org.springframework.web.context.request.async.WebAsyncManager$4.run(WebAsyncManager.java:316) ~[spring-web-4.3.5.RELEASE.jar:4.3.5.RELEASE]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_71]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_71]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_71]
2017-02-08 23:27:36.238  INFO 1551 --- [nio-8080-exec-2] c.p.config.TraceAsyncRequestInterceptor  : afterCompletion CALLED,thread:Thread[http-nio-8080-exec-2,5,main]
2017-02-08 23:27:36.238  INFO 1551 --- [nio-8080-exec-2] c.p.config.TraceAsyncRequestInterceptor  : afterCompletion CALLED,thread:Thread[http-nio-8080-exec-2,5,main]

task抛出异常,还是会调用postProcess
afterCompletion在响应线程执行了两次

加上spring filter

2017-02-09 00:03:17.711  INFO 1672 --- [nio-8080-exec-1] com.xixicat.config.TraceFilter        : OncePerRequestFilter before,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:03:17.724  INFO 1672 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Request received,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:03:17.724  INFO 1672 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Servlet thread released,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:03:17.726  INFO 1672 --- [nio-8080-exec-1] c.p.config.TraceAsyncRequestInterceptor  : beforeConcurrentHandling get from mdc:null,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:03:17.729  INFO 1672 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : preProcess get from mdc:null,thread:Thread[MvcAsync1,5,main]
2017-02-09 00:03:17.729  INFO 1672 --- [nio-8080-exec-1] com.xixicat.config.TraceFilter        : OncePerRequestFilter after,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:03:22.730  INFO 1672 --- [      MvcAsync1] com.xixicat.service.TaskService       : task service get from mdc:localhost get by mdc,thread:Thread[MvcAsync1,5,main]
2017-02-09 00:03:22.730  INFO 1672 --- [      MvcAsync1] com.xixicat.service.TaskService       : Slow task executed,thread:Thread[MvcAsync1,5,main]
2017-02-09 00:03:22.730  INFO 1672 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : postProcess CALLED,thread:Thread[MvcAsync1,5,main]
2017-02-09 00:03:22.750  INFO 1672 --- [nio-8080-exec-2] c.p.config.TraceAsyncRequestInterceptor  : afterCompletion CALLED,thread:Thread[http-nio-8080-exec-2,5,main]

加上MDC

2017-02-09 00:05:46.870  INFO 1682 --- [nio-8080-exec-1] com.xixicat.config.TraceFilter        : OncePerRequestFilter before,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:05:46.883  INFO 1682 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Request received,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:05:46.884  INFO 1682 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Servlet thread released,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:05:46.886  INFO 1682 --- [nio-8080-exec-1] c.p.config.TraceAsyncRequestInterceptor  : beforeConcurrentHandling get from mdc:remote ip set from OncePerRequestFilter,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:05:46.889  INFO 1682 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : preProcess get from mdc:null,thread:Thread[MvcAsync1,5,main]
2017-02-09 00:05:46.889  INFO 1682 --- [nio-8080-exec-1] com.xixicat.config.TraceFilter        : OncePerRequestFilter after,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:05:51.891  INFO 1682 --- [      MvcAsync1] com.xixicat.service.TaskService       : task service get from mdc:remote ip set from OncePerRequestFilter,thread:Thread[MvcAsync1,5,main]
2017-02-09 00:05:51.891  INFO 1682 --- [      MvcAsync1] com.xixicat.service.TaskService       : Slow task executed,thread:Thread[MvcAsync1,5,main]
2017-02-09 00:05:51.891  INFO 1682 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : postProcess CALLED,thread:Thread[MvcAsync1,5,main]
2017-02-09 00:05:51.914  INFO 1682 --- [nio-8080-exec-2] c.p.config.TraceAsyncRequestInterceptor  : afterCompletion CALLED,thread:Thread[http-nio-8080-exec-2,5,main]

block

2017-02-09 00:08:52.271  INFO 1691 --- [nio-8080-exec-1] com.xixicat.config.TraceFilter        : OncePerRequestFilter before,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:08:52.284  INFO 1691 --- [nio-8080-exec-1] c.p.controller.BlockingController        : Request received,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:08:57.291  INFO 1691 --- [nio-8080-exec-1] com.xixicat.service.TaskService       : task service get from mdc:remote ip set from OncePerRequestFilter,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:08:57.291  INFO 1691 --- [nio-8080-exec-1] com.xixicat.service.TaskService       : Slow task executed,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:08:57.291  INFO 1691 --- [nio-8080-exec-1] c.p.controller.BlockingController        : Servlet thread released,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:08:57.305  INFO 1691 --- [nio-8080-exec-1] com.xixicat.config.TraceFilter        : OncePerRequestFilter after,thread:Thread[http-nio-8080-exec-1,5,main]

总结

• OncePerRequestFilter里头before添加MDC,after删除MDC,这个是请求线程的

• CallableProcessingInterceptorAdapter这个preProcess添加到异步线程MDC,postProcess删除异步线程MDC

doc

• 理解Callable 和 Spring DeferredResult（翻译）