springboot異步mvc使用threadlocal的正確姿式

時間 2019-11-07

標籤 springboot 異步 mvc 使用 threadlocal 正確欄目 Spring 简体版

原文原文鏈接

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是在響應線程html

或者java

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秒時,異步線程執行完,執行postProcessweb

沒有超時,但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

加上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]