你好哇,我是歪歪。 前几天在网上冲浪的时候看到一篇技术文章,讲的是他把一个request请求传递到了线程池里面,然后遇到了一个匪夷所思的情况。 他写了这篇文章,把自己针对这个问题的探索过程分享了出来: 《springboot中如何正确的在异步线程中使用request》 https:www。cnblogs。commysgkp16470336。html 文章还是挺不错的,把发现问题和解决问题都写的很明白了。 但是,我觉得把探索问题的部分写的太省略了,导致我看完之后都不知道这个问题的根本原因是什么。 而为什么我会对这篇文章特别感兴趣呢? 因为这个坑我记得我刚刚入行没两年的也遇到过,我已经不记得自己当时是怎么解决的了,但是我肯定也没有深入的去研究。 因为那个时候遇到问题,就去网上费尽心思的查,粘一个方案过来看能不能用。 如果不能用的话,心里暗骂一句:小可(S)爱(B),然后接着找。 直到找到一个可以用的。 至于为什么能用? 管它呢,研究这玩意干啥。 主要是当时觉得探索这个玩意到进入到源码里面去,一涉及到源码心里就犯怵,所以就敬而远之。 现在不一样了,现在我看到源码我就觉得兴奋,心里想着:多好的素材啊。 既然这次又让我遇到了,所以我决定把几年前的坑填上,盘一盘它。 搞个Demo 由于这个现象太过匪夷所思,所以写文章的那个老哥认为这个是一个BUG,还在Spring的github上提了一个issues: https:github。comspringprojectsspringframeworkissues28741 这里面他附上了一个可以复现的Demo,所以我就直接拿来用了。 确实是可以复现,但是其实他提供的这个Demo还是有点臃肿,具有一点点的迷惑性,直接给我迷晕了,让我在这上面稍微花了时间。 先给你看一下他的Demo是怎么样的。 主要是两个Controller接口。 第一个接口是get请求类型的getParams,代码很简单,先放在这里,等下用: 第二个接口是post请求类型的postTest,就这么几行代码:PostMapping(postTest)publicStringpostTest(HttpServletRequestrequest){Stringage1request。getParameter(age);Stringname1request。getParameter(name);System。out。println(age1age1,name1name1);newThread(newRunnable(){Overridepublicvoidrun(){Stringage2request。getParameter(age);Stringname2request。getParameter(name);System。out。println(age2age2,name2name2);模拟业务请求try{Thread。sleep(200);}catch(InterruptedExceptione){thrownewRuntimeException(e);}age2request。getParameter(age);name2request。getParameter(name);}})。start();} 主要是里面启动了一个线程,在线程里面有从request里面获取参数的动作。 这个方法访问起来是这样的一个情况: 从age2、name2输出上看,虽然request传入到异步线程里面了,但是还是能从里面获取到对应的参数,没有看出来有什么毛病。 但是接下来,匪夷所思的事情就要出现了。 还记得我们前面的getParams接口吗? 我再把它拿过来给你看一眼: 你说,就这个接口,我用下面这个链接去访问,在我的认知里面是完全不可能有任何问题的,对吧? http:127。0。0。1:8080getParams?a1b2 但是,这玩意还真的就打破了我的认知: 在访问postTest方法之后,再次访问getParams方法,getParams方法居然抛出异常了? 抛出的异常是说我调用的时候没有传递b这个参数。 但是我的链接里面明明就是有b2的啊? 这玩意上哪里说理去? 上面就是那位老哥提供的可复现的Demo的主要部分。 但是我前面说了,这个Demo有点臃肿,具有一点点迷惑性。 首先如果我再加一个输出语句,那么在一个短暂的sleep之后,age2和name2就没了: 虽然还是感觉有点神奇吧,但是也没有刚刚那个操作让我感到震惊。 因为从输出null这个结果,我至少可以知道程序在这个地方就出现问题了,把问题的范围限定在了一次请求中。 刚刚那个操作,好家伙,表现出来到情况是这样的:先发起一个post请求,看起来是正常的。然后再发起一个get请求,这个get请求挂了。但是这个get请求从发起的角度来看找不到任何毛病。 你要基于上面这个情况去分析问题的话,就不好找问题了,毕竟要发起两个毫不相干的请求才能触发问题。 加入一行输出日志,相当于把问题简化了一点。 但是你看到的是我就加了一行输出日志,实际上等我加这行日志的时候,我拿到这个Demo已经过去了好几个小时了。 在这期间我也一直以为必须要按照这个流程来操作,才能复现问题。 所以我才说具有一点点迷惑性。 好,现在不管怎么说吧。 我先把Demo简化一点,便于继续分析。我的Demo可以简化到这个程度:GetMapping(getTest)publicStringgetTest(HttpServletRequestrequest){Stringagerequest。getParameter(age);System。out。println(ageage);newThread((){try{Thread。sleep(200);}catch(InterruptedExceptione){thrownewRuntimeException(e);}Stringage1request。getParameter(age);System。out。println(age1age1);})。start();} get和post请求都可以,只是我为了方便选择发起get请求。 然后只需要传递一个参数就行,核心步骤是要把request传递到异步线程里面去,调用getParameter再次获取对应入参。 你可以把上面的代码粘到你本地,把项目跑起来,然后调一次下面这个链接: http:127。0。0。1:8080getTest?age18 从控制台你可以看到这样的输出: 到这里就复现了前面说的问题。 但是你別着急,你再次发起调用,你会看到控制台的输出是这样的: 怎么样,是不是很神奇,很懵逼? 为了让你更加直观的懵逼,我给你上个动图,发起两次调用,主要关注控制台的输出: 好,现在,你就去泡杯茶,点根烟,慢慢去琢磨,这玩意是不是属于超自然现象。 探索 其实我看到这个现象的时候并不是特别的震惊,毕竟写文章这几年,什么稀奇古怪的现象都遇到过。 所以我只是轻蔑一笑,看向了我排查问题的武器库,很快就看到了一个比较趁手的东西:开启Debug日志。 如果是以前,对于这种没有抛出异常的问题跟着,由于没有异常堆栈,我肯定是迫不及待的正向的Debug跟了一下源码,扎到源码里面去一顿狂翻,左看右看。 但是结果常常是一头扎进去之后,很快就迷失了,搞了好几个小时才从源码里面爬出来,出来的时候基本上一无所获。 但是我现在不会这么猴急了,现在就成熟了很多。遇到这类问题不会先急着去卷源码会先多从日志里面挖掘一点东西出来。 所以我遇到这个问题的第一反应就是调整日志级别到Debug: logging。level。rootdebug 观察日志这个小技巧我在之前的文章里面也分享过。 当日志调整到Debug级别之后,再次发起两次调用,问题复现,同时把日志拿出来做对比。 两次请求的Debug日志整体情况是这样的,左边是第一次请求,右边是第二次请求: 可以看到第一次请求比第二次请求的日志多。 多说明什么问题? 是不是说明第一次请求调用的方法更多一点? 为什么多一点,到底是哪些方法只调用了一次? 我也不知道,但是我能从Debug日志里面梳理出来。 比如下面这个图就是梳理出来的第一次请求多打印的日志: 很快我就从Debug日志里面看到了一个我觉得很可疑的地方: Startprocessingwithinput〔age18〕 这一行日志,只有第一次请求的时候打印了,从日志表达的意思来看,是处理请求里面的age18。 为什么第二次不打印呢? 我也不知道,但是我知道了第一个关键断点打在什么位置了。 全局搜索关键字Startprocessingwithinput可以找到配置文件里面的parameters。bytes。 然后全局搜索parameters。bytes,就能找到是在Parameters。java文件里面输出的: 也就是这个地方: org。apache。tomcat。util。http。ParametersprocessParameters(byte〔〕,int,int,java。nio。charset。Charset) 找到第一个断点,就找到了突破口,只要好好的拿捏住,之后的事情就基本上就顺风顺水了。 首先,重启项目,发起调用,在断点处看调用堆栈: 接下来的思路是什么? 就是我要从堆栈里面找到一个东西。 你想啊,第一次请求走这个地方,第二次请求就不走这个地方了,所以一定有个类似于这样的逻辑:if(满足某个条件){走processParameters方法} 所以,只需要往回找五个调用栈,我就找到了这一个方法: org。apache。catalina。connector。RequestgetParameter 这个时候你看旁边的parametersParsed参数是true,按理来说true不应该走进if分支呀? 因为这个地方我们是从断点处的堆栈信息往回找,在从parseParameters方法到processParameters方法之间,肯定有地方修改了parametersParsed参数的值为true。 这一点,从parametersParsed的初始值是false也能看出来: 因此,我决定把第二个断点打在getParameter方法中: 再次重启服务,发起调用,parametersParsed为false,开始执行parseParameters()方法解析参数: 而解析参数的目的之一就是把我的age18放到paramHashValues这个Map容器里面: org。apache。tomcat。util。http。ParametersaddParameter parseParameters()方法执行完成之后,接着从前面的paramHashValues容器里面把age对应的18返回回去: 但是,朋友们,注意上面的图片中有个标号为的地方: 这个方法,在parseParameters方法里面也会被调用: org。apache。tomcat。util。http。ParametershandleQueryParameters 好,现在打起精神来听我说。 handleQueryParameters方法才是真正解析参数的方法,为了防止重复解析它加入了这样的逻辑: didQueryParameters初始为false,随后被设置为true。 这个很好理解,入参解析一次就行了,解析的产物一个Map,后续要拿参数对应的值,从Map里面获取即可。 比如我把入参修改为这样: http:127。0。0。1:8080getTest?a1b2c3d4 那么经过解析之后,这个Map就变成了这样: 经过了前面的这一顿折腾之后,现在找到了解析入参的方法。 那么全文的关键点就在didQueryParameters这个参数的变化了。 只有是false的时候才会去解析入参。 那么我接下来的排查思路就是观察didQueryParameters参数的变化,所以在字段上打上断点,重启项目,继续调试: 第一次进入这个方法的时候didQueryParameters为false,入参是age18: 而第一次进入这个方法的原因我前面也说了,是因为触发了parseParameters的逻辑: 第二次进入这个方法didQueryParameters变为true了,不用再次解析: 那么第二次进入这个方法的原因是什么? 前面也说了,getParameter方法的第一行就是触发解析的逻辑: 接下来,断点停在了这个地方: org。apache。tomcat。util。http。Parametersrecycle 方法叫做recycle,表明是循环再利用,在这里面会把存放参数的Map清空,把didQueryParameters再次设置为了false。 而当你用同样的手段去观察parametersParsed参数,也就是这个参数的时候: 会发现它也有一个recycle方法: org。apache。catalina。connector。Requestrecycle 这个方法上的注释,也有一个特别扎眼的词:reuse。 注释过来是这样的:释放所有的对象引用,并初始化实例变量,为重新使用这个对象做准备。 种种迹象表明request在tomcat里面是循环使用的。 虽然在这之前我也知道是循环使用的,但是百闻不如一见嘛。这次是我Debug的时候亲眼看到了。 又拿捏一个小细节。 由于我们在异步线程里面还触发了一次getParameter方法: 但是getTest方法已经完成了响应,这个时候Request可能已经完成了回收。 注意我说的是可能,因为这个时候Request的回收动作和异步线程谁先谁后还不一定。 这也解释了这个现象: 虽然request传入到异步线程里面了,但是还是能从里面获取到对应的参数。 因为此时request的回收动作还没做完,还可以继续获取参数。 为了避免这个可能,我把sleep的时间调整为5s,保证request完成回收。 然后这异步线程里面继续Debug,接下来神奇的事情就要开始了。 再次触发handleQueryParameters的时候,didQueryParameters由于被recycle了,所以变成了false。 然后执行解析的逻辑,把didQueryParameters设置为true。 但是,我们可以看到,此时查询的内容却没有了,是个null: 这个也好理解,肯定是随着调用结束,被recycle了嘛: 所以,到这里我能解答为什么异步线程里面的输出是null了。 queryMB就是我调用的时候传入的age18。 通过Debug发现异步线程里面调用getParameter的时候没有queryMB,所以就不会解析出Map。 没有Map,异步线程里面的输出肯定是null。 为什么没有queryMB呢? 因为当前这个请求已经被返回了,执行了recycle相关操作,queryMB就是在这个时候没有的。 那么为什么再次发起调用,会出现这个神奇的现象呢? 很简单,因为在异步线程里面调用getParameter的时候,把didQueryParameters设置为true了。 但是异步线程里面的调用,超出了request的生命周期,所以并不会再次触发request的recycle相关操作,因此这个request拿来复用的时候didQueryParameters还是true。 所以,从Debug来看,虽然queryMB是有值的,但是没用啊,didQueryParameters是true,程序直接return了,不会去解析你的入参: 问题得到解答。 此时,我们再回到最开始的这个方法中: 你想想为什么这个方法调用的时候出现异常了? 还是一样的道理呀,由于request是复用的,虽然你传入了参数b,但是由于前一个请求在异步线程里面调用了getParameter方法,将didQueryParameters设置为了true,导致程序不会去解析我传入的a1b2。 从调用链接的角度来说,虽然我们调用的是这个链接: http:127。0。0。1:8080getParams?a1b2 但是对于程序来说,它等效于这个链接: http:127。0。0。1:8080getParams 由于入参b是int类型的,那可不就是会抛出这个异常吗: 这个异常是说:哥们,你要么把b搞成Integer类型的,不传值我就给你赋为null。要么给我传一个值。 你现在用int来接受,又不给我值,我这没法处理啊? 我能给你默认赋值一个0吗? 肯定不能啊,0和null可不是一个含义,万一你程序出异常了,把锅甩给我怎么办? 算了,我还是抛异常吧,最稳妥了。 所以你看,要是你从这个抛异常的地方去找答案,也许能找到,但是路就走远了一点。 因为这个地方并不是问题的根因。 到这里,你应该清楚这个BUG到底是怎么回事了。request的生命周期 在探索这个问题的过程中,我也想到了另外一个问题: 一个request请求的生命周期是怎么样的? 这题我记得几年前我背过,现在我确实有点想不起来了,但是我知道去哪里找答案。 JavaServletSpecification,这是一份规范,答案就藏在这个规范里面: https:javaee。github。ioservletspecdownloadsservlet4。0servlet40FINAL。pdf 在3。13小节里面,关于request这个Object的生命周期,规范是这样说的: 这寥寥数语,非常关键,所以我一句句的拆解给你看。 Eachrequestobjectisvalidonlywithinthescopeofaservlet’sservicemethod,orwithinthescopeofafilter’sdoFiltermethod,unlesstheasynchronousprocessingisenabledforthecomponentandthestartAsyncmethodisinvokedontherequestobject。 一上来就是一个长句,但是根本不要慌。 你知道的,我英语八级半,水平一向是可以的。 先把长句拆短一点,我可以先只翻译unless之前的部分。 前面这部分说:每个request对象只在servlet的服务方法的范围内有效,或者在过滤器的doFilter方法的范围内有效。 接着它来了一个unless,表示转折,和but差不多。 我们主要关注unless后面这句: theasynchronousprocessingisenabledforthecomponentandthestartAsyncmethodisinvokedontherequestobject。 组件的异步处理功能被启用,并且在request上调用了startAsync方法。 也就是说,request的生命周期在遇到异步的时候有点特殊,但是这个异步又不是我前面演示的那种异步。 关于异步,规范中提到了request里面有个方法:startAsync。 我去看了一眼,果然是有: 返回值是一个叫做AsyncContext的东西。 但是我先按下不表,接着往下翻译。 Inthecasewhereasynchronousprocessingoccurs,therequestobjectremainsvaliduntilcompleteisinvokedontheAsyncContext。 在发生异步处理的情况下,request对象的生命周期一直会延续到在AsyncContext上调用complete方法之前。 这里又提到了一个complete方法,这个complete方法invokedontheAsyncContext。 AsyncContext是什么玩意? 不就是request。startAsync()方法的返回值吗? 果然在AsyncContext里面有个complete方法: 不慌,继续按下不表,一会就回收,接着往下看。 Containerscommonlyrecyclerequestobjectsinordertoavoidtheperformanceoverheadofrequestobjectcreation。 容器通常会recycle请求对象,以避免创建请求对象的性能开销。 看到这个recycle我们就很眼熟了,原来规范里面是建议了容器里面实现request的时候尽量复用,而不是回收,目的是节约性能。 这玩意,属于意外收获呀。 最后一句话是这样的: ThedevelopermustbeawarethatmaintainingreferencestorequestobjectsforwhichstartAsynchasnotbeencalledoutsidethescopedescribedaboveisnotrecommendedasitmayhaveindeterminateresults。 这句话是说:程序员朋友们必须要意识到,我不建议在上述范围之外维护request的引用,因为它可能会产生不确定的结果。 看到这个不确定的结果时我很开心,因为我前面已经演示过了,确实会产生莫名其妙的结果。 但是规范里面在scope之前还加了一个限定词:startAsynchasnotbeencalled。 反过来说,意思就是如果你有一个调用了startAsync方法的request,那么在上述范围之外,你还可以操作这个request,也不会有问题。 这一整段话中,我们提炼到了两个关键的方法:request的startAsync方法AsyncContext的complete方法 根据规范来说,这两个方法才是request异步编程的正确打开方式。正确打开方式 在这之前,假设你完全不知道startAsync和complete方法。 但是看了规范上的描述,猜也能猜出来代码应该这样写,然后发起多次调用,没有任何毛病: 这就是正确的打开方式。 从现象上来说,就是getTest请求返回之后,request线程并没有被调用recycle方法进行回收。 为什么这样写就能实现request的异步化呢? 用脚指头想也能想到,一定有一个这样的判断逻辑存在:if(调用过request的startAsync方法){先不回收} 所以,用之前的方法,在recycle方法上打断点,并往回找,很快就能找到这个方法: 然后,关于AsyncContext的complete方法我还注意到它有这样的一个描述: 也就是说在调用complete方法之后response流才会关闭,那么有意思的就来了: 我不仅在异步线程里面可以操作request还可以操作response。 但是转念一想,既然都是异步编程了,操作response的意义肯定比操作request的意义更大。 关于Tomcat对于异步请求的支持还有很多可以探索的地方,自己慢慢去玩吧。 写到这里的时候我发现标题说的也不对,标题是:千万不要把Request传递到异步线程里面!有坑! 而正确的说法应该是: 千万不要随便把Request传递到异步线程里面!有坑!你拿捏不住,得用startAsync方法才行。 好了,就这样吧,本文写到这里就差不多了。 本文主要是分享了一下request放到异步线程之后的诡异现象和排查方法,最后也给出了正确的打开方式。 希望你能掌握到这样的一个问题排查方法,不要惧怕问题,要抽丝剥茧的干它。 然后,其实和BUG排查比起来,关于request的异步编程相关的知识更加重要,本文只是做了一个小小的引子,如果这块知识对你是空白的,希望你有兴趣的话自己去研究一下,很有价值。 最后,我想说的是,关于之前文章的一个留言: 从看到这个现象,到写完这篇文章,我不断的调试程序,至少重启了近百次服务,发起了上百次请求。在源码里面也走了一些弯路,最后才抽丝剥茧的看到本问题的根因。 所以,我排查问题的经验就一个字: