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
