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

头像
codecraft
    阅读 10 分钟

    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

    springboot
    codecraft
    11.9k 声望2k 粉丝

    当一个代码的工匠回首往事时，不因虚度年华而悔恨，也不因碌碌无为而羞愧，这样，当他老的时候，可以很自豪告诉世人，我曾经将代码注入生命去打造互联网的浪潮之巅，那是个很疯狂的时代，我在一波波的浪潮上留下...

    « 上一篇
    nginx的upstream异常
    下一篇 »
    jdbc连接pg数据库timeout

    引用和评论

    推荐阅读
    头像
    Java23的新特性

    codecraft赞 1阅读 569

    头像
    Spring boot连接Minio实现文件的上传以及下载

    zZ_jie赞 2阅读 3.7k

    头像
    一套全新的 Java 技术栈，一种现代化的 Java 编程方式。

    ccmjga赞 2阅读 3.8k评论 1

    头像
    实现 Angular 程序处理进度条

    kexb赞 3阅读 363

    头像
    Specifications 构建动态查询

    吴季分赞 3阅读 344

    头像
    记录下解决自定义 Feign 调用，响应content-type 格式不正确导致的解析错误

    kexb赞 2阅读 727

    头像
    如何让Spring MVC显示自定义的404 Not Found页面

    注销阅读 2.8k

    0 条评论
    得票最新