千萬不要把Request傳遞到非同步執行緒裡面!有坑!

2022-07-18 15:04:56

你好哇,我是歪歪。

前幾天在網上衝浪的時候看到一篇技術文章,講的是他把一個 request 請求傳遞到了執行緒池裡面,然後遇到了一個匪夷所思的情況。

他寫了這篇文章,把自己針對這個問題的探索過程分享了出來:

《springboot 中如何正確的在非同步執行緒中使用request》
https://www.cnblogs.com/mysgk/p/16470336.html

文章還是挺不錯的,把發現問題和解決問題都寫的很明白了。

但是,我覺得把探索問題的部分寫的太省略了,導致我看完之後都不知道這個問題的根本原因是什麼。

而為什麼我會對這篇文章特別感興趣呢?

因為這個「坑」我記得我剛剛入行沒兩年的也遇到過,我已經不記得自己當時是怎麼解決的了,但是我肯定也沒有深入的去研究。

因為那個時候遇到問題,就去網上費盡心思的查,粘一個方案過來看能不能用。

如果不能用的話,心裡暗罵一句:小可(S)愛(B),然後接著找。

直到找到一個可以用的。

至於為什麼能用?

管它呢,研究這玩意幹啥。

主要是當時覺得探索這個玩意到進入到原始碼裡面去,一涉及到原始碼心裡就犯怵,所以就敬而遠之。

現在不一樣了,現在我看到原始碼我就覺得興奮,心裡想著:多好的素材啊。

既然這次又讓我遇到了,所以我決定把幾年前的坑填上,盤一盤它。

搞個 Demo

由於這個現象太過匪夷所思,所以寫文章的那個老哥認為這個是一個 BUG,還在 Spring 的 github 上提了一個 issues:

https://github.com/spring-projects/spring-framework/issues/28741

這裡面他附上了一個可以復現的 Demo,所以我就直接拿來用了。

確實是可以復現,但是其實他提供的這個 Demo 還是有點臃腫,具有一點點的迷惑性,直接給我迷暈了,讓我在這上面稍微花了時間。

先給你看一下他的 Demo 是怎麼樣的。

主要是兩個 Controller 介面。

第一個介面是 get 請求型別的 getParams,程式碼很簡單,先放在這裡,等下用:

第二個介面是 post 請求型別的 postTest,就這麼幾行程式碼:

@PostMapping("/postTest")
public String postTest(HttpServletRequest request) {
    String age1 = request.getParameter("age");
    String name1 = request.getParameter("name");
    System.out.println("age1=" + age1 + ",name1=" + name1);
    new Thread(new Runnable() {
        @Override
        public void run() {
            String age2 = request.getParameter("age");
            String name2 = request.getParameter("name");
            System.out.println("age2=" + age2 + ",name2=" + name2);
            //模擬業務請求
            try {
                Thread.sleep(200);
            } catch (InterruptedException e) {
                throw new RuntimeException(e);
            }
            age2 = request.getParameter("age");
            name2 = request.getParameter("name");
        }
    }).start();
    return "post success";
}

主要是裡面啟動了一個執行緒,線上程裡面有從 request 裡面獲取引數的動作。

這個方法存取起來是這樣的一個情況:

從 age2、name2 輸出上看,雖然 request 傳入到非同步執行緒裡面了,但是還是能從裡面獲取到對應的引數,沒有看出來有什麼毛病。

但是接下來,匪夷所思的事情就要出現了。

還記得我們前面的 getParams 介面嗎?

我再把它拿過來給你看一眼:

你說,就這個介面,我用下面這個連結去存取,在我的認知裡面是完全不可能有任何問題的,對吧?

http://127.0.0.1:8080/getParams?a=1&b=2

但是,這玩意還真的就打破了我的認知:

在存取 postTest 方法之後,再次存取 getParams 方法,getParams 方法居然丟擲異常了?

丟擲的異常是說我呼叫的時候沒有傳遞 b 這個引數。

但是我的連結裡面明明就是有 b=2 的啊?

這玩意上哪裡說理去?

上面就是那位老哥提供的可復現的 Demo 的主要部分。

但是我前面說了,這個 Demo 有點臃腫,具有一點點迷惑性。

首先如果我再加一個輸出語句,那麼在一個短暫的 sleep 之後, age2 和 name2 就沒了:

雖然還是感覺有點神奇吧,但是也沒有剛剛那個操作讓我感到震驚。

因為從輸出 null 這個結果,我至少可以知道程式在這個地方就出現問題了,把問題的範圍限定在了一次請求中。

剛剛那個操作,好傢伙,表現出來到情況是這樣的:

  • 先發起一個 post 請求,看起來是正常的。
  • 然後再發起一個 get 請求,這個 get 請求掛了。
  • 但是這個 get 請求從發起的角度來看找不到任何毛病。

你要基於上面這個情況去分析問題的話,就不好找問題了,畢竟要發起兩個毫不相干的請求才能觸發問題。

加入一行輸出紀錄檔,相當於把問題簡化了一點。

但是你看到的是我就加了一行輸出紀錄檔,實際上等我加這行紀錄檔的時候,我拿到這個 Demo 已經過去了好幾個小時了。

在這期間我也一直以為必須要按照這個流程來操作,才能復現問題。

所以我才說具有一點點迷惑性。

好,現在不管怎麼說吧。

我先把 Demo 簡化一點,便於繼續分析。我的 Demo 可以簡化到這個程度:

@GetMapping("/getTest")
public String getTest(HttpServletRequest request) {
    String age = request.getParameter("age");
    System.out.println("age=" + age);
    new Thread(() -> {
        try {
            Thread.sleep(200);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
        String age1 = request.getParameter("age");
        System.out.println("age1=" + age1);
    }).start();
    return "success";
}

get 和 post 請求都可以,只是我為了方便選擇發起 get 請求。

然後只需要傳遞一個引數就行,核心步驟是要把 request 傳遞到非同步執行緒裡面去,呼叫 getParameter 再次獲取對應入參。

你可以把上面的程式碼粘到你本地,把專案跑起來,然後調一次下面這個連結:

http://127.0.0.1:8080/getTest?age=18

從控制檯你可以看到這樣的輸出:

到這裡就復現了前面說的問題。

但是你別著急,你再次發起呼叫,你會看到控制檯的輸出是這樣的:

怎麼樣,是不是很神奇,很懵逼?

為了讓你更加直觀的懵逼,我給你上個動圖,發起兩次呼叫,主要關注控制檯的輸出:

好,現在,你就去泡杯茶,點根菸,慢慢去琢磨,這玩意是不是屬於超自然現象。

探索

其實我看到這個現象的時候並不是特別的震驚,畢竟寫文章這幾年,什麼稀奇古怪的現象都遇到過。

所以我只是輕蔑一笑,看向了我排查問題的武器庫,很快就看到了一個比較趁手的東西:開啟 Debug 紀錄檔。

如果是以前,對於這種沒有丟擲異常的問題跟著,由於沒有異常堆疊,我肯定是迫不及待的正向的 Debug 跟了一下原始碼,扎到原始碼裡面去一頓狂翻,左看右看。

但是結果常常是一頭扎進去之後,很快就迷失了,搞了好幾個小時才從原始碼裡面爬出來,出來的時候基本上一無所獲。

但是我現在不會這麼猴急了,現在就成熟了很多。遇到這類問題不會先急著去卷原始碼會先多從紀錄檔裡面挖掘一點東西出來。

所以我遇到這個問題的第一反應就是調整紀錄檔級別到 Debug:

logging.level.root=debug

觀察紀錄檔這個小技巧我在之前的文章裡面也分享過。

當紀錄檔調整到 Debug 級別之後,再次發起兩次呼叫,問題復現,同時把紀錄檔拿出來做對比。

兩次請求的 Debug 紀錄檔整體情況是這樣的,左邊是第一次請求,右邊是第二次請求:

可以看到第一次請求比第二次請求的紀錄檔多。

多說明什麼問題?

是不是說明第一次請求呼叫的方法更多一點?

為什麼多一點,到底是哪些方法只呼叫了一次?

我也不知道,但是我能從 Debug 紀錄檔裡面梳理出來。

比如下面這個圖就是梳理出來的第一次請求多列印的紀錄檔:

很快我就從 Debug 紀錄檔裡面看到了一個我覺得很可疑的地方:

Start processing with input [age=18]

這一行紀錄檔,只有第一次請求的時候列印了,從紀錄檔表達的意思來看,是處理請求裡面的 age=18。

為什麼第二次不列印呢?

我也不知道,但是我知道了第一個關鍵斷點打在什麼位置了。

全域性搜尋鍵碼 「Start processing with input」 可以找到組態檔裡面的 「parameters.bytes」。

然後全域性搜尋 「parameters.bytes」,就能找到是在 Parameters.java 檔案裡面輸出的:

也就是這個地方:

org.apache.tomcat.util.http.Parameters#processParameters(byte[], int, int, java.nio.charset.Charset)

找到第一個斷點,就找到了突破口,只要好好的拿捏住,之後的事情就基本上就順風順水了。

首先,重啟專案,發起呼叫,在斷點處看呼叫堆疊:

接下來的思路是什麼?

就是我要從堆疊裡面找到一個東西。

你想啊,第一次請求走這個地方,第二次請求就不走這個地方了,所以一定有個類似於這樣的邏輯:

if(滿足某個條件){
    走processParameters方法
}

所以,只需要往回找五個呼叫棧,我就找到了這一個方法:

org.apache.catalina.connector.Request#getParameter

這個時候你看旁邊的 parametersParsed 引數是 true,按理來說 true 不應該走進 if 分支呀?

因為這個地方我們是從斷點處的堆疊資訊往回找,在從 parseParameters 方法到 processParameters 方法之間,肯定有地方修改了 parametersParsed 引數的值為 true。

這一點,從 parametersParsed 的初始值是 false 也能看出來:

因此,我決定把第二個斷點打在 getParameter 方法中:

再次重啟服務,發起呼叫,parametersParsed 為 false,開始執行 parseParameters() 方法解析引數:

而解析引數的目的之一就是把我的 age=18 放到 paramHashValues 這個 Map 容器裡面:

org.apache.tomcat.util.http.Parameters#addParameter

parseParameters() 方法執行完成之後,接著從前面的 paramHashValues 容器裡面把 age 對應的 18 返回回去:

但是,朋友們,注意上面的圖片中有個標號為 ① 的地方:

這個方法,在 parseParameters 方法裡面也會被呼叫:

org.apache.tomcat.util.http.Parameters#handleQueryParameters

好,現在打起精神來聽我說。

handleQueryParameters 方法才是真正解析引數的方法,為了防止重複解析它加入了這樣的邏輯:

didQueryParameters 初始為 false,隨後被設定為 true。

這個很好理解,入參解析一次就行了,解析的產物一個 Map,後續要拿引數對應的值,從 Map 裡面獲取即可。

比如我把入參修改為這樣:

http://127.0.0.1:8080/getTest?a=1&b=2&c=3&d=4

那麼經過解析之後,這個 Map 就變成了這樣:

經過了前面的這一頓折騰之後,現在找到了解析入參的方法。

那麼全文的關鍵點就在 didQueryParameters 這個引數的變化了。

只有是 false 的時候才會去解析入參。

那麼我接下來的排查思路就是觀察 didQueryParameters 引數的變化,所以在欄位上打上斷點,重啟專案,繼續偵錯:

第一次進入這個方法的時候 didQueryParameters 為 false,入參是 age=18:

而第一次進入這個方法的原因我前面也說了,是因為觸發了 parseParameters 的邏輯:

第二次進入這個方法 didQueryParameters 變為 true 了,不用再次解析:

那麼第二次進入這個方法的原因是什麼?

前面也說了,getParameter 方法的第一行就是觸發解析的邏輯:

接下來,斷點停在了這個地方:

org.apache.tomcat.util.http.Parameters#recycle

方法叫做 recycle,表明是迴圈再利用,在這裡面會把存放引數的 Map 清空,把 didQueryParameters 再次設定為了 false。

而當你用同樣的手段去觀察 parametersParsed 引數,也就是這個引數的時候:

會發現它也有一個 recycle 方法:

org.apache.catalina.connector.Request#recycle

這個方法上的註釋,也有一個特別扎眼的詞:reuse。

註釋過來是這樣的:釋放所有的物件參照,並初始化範例變數,為重新使用這個物件做準備。

種種跡象表明 request 在 tomcat 裡面是迴圈使用的。

雖然在這之前我也知道是迴圈使用的,但是百聞不如一見嘛。這次是我 Debug 的時候親眼看到了。

又拿捏一個小細節。

由於我們在非同步執行緒裡面還觸發了一次 getParameter 方法:

但是 getTest 方法已經完成了響應,這個時候 Request 可能已經完成了回收。

注意我說的是「可能」,因為這個時候 Request 的回收動作和非同步執行緒誰先誰後還不一定。

這也解釋了這個現象:

雖然 request 傳入到非同步執行緒裡面了,但是還是能從裡面獲取到對應的引數。

因為此時 request 的回收動作還沒做完,還可以繼續獲取引數。

為了避免這個「可能」,我把 sleep 的時間調整為 5s,保證 request 完成回收。

然後這非同步執行緒裡面繼續 Debug,接下來神奇的事情就要開始了。

再次觸發 handleQueryParameters 的時候,didQueryParameters 由於被 recycle 了,所以變成了 false。

然後執行解析的邏輯,把 didQueryParameters 設定為 true。

但是,我們可以看到,此時查詢的內容卻沒有了,是個 null:

這個也好理解,肯定是隨著呼叫結束,被 recycle 了嘛:

所以,到這裡我能解答為什麼非同步執行緒裡面的輸出是 null 了。

queryMB 就是我呼叫的時候傳入的 age=18。

通過 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,導致程式不會去解析我傳入的 a=1&b=2。

從呼叫連結的角度來說,雖然我們呼叫的是這個連結:

http://127.0.0.1:8080/getParams?a=1&b=2

但是對於程式來說,它等效於這個連結:

http://127.0.0.1:8080/getParams

由於入參 b 是 int 型別的,那可不就是會丟擲這個異常嗎:

這個異常是說:哥們,你要麼把 b 搞成 Integer 型別的,不傳值我就給你賦為 null。要麼給我傳一個值。

你現在用 int 來接受,又不給我值,我這沒法處理啊?

我能給你預設賦值一個 0 嗎?

肯定不能啊,0 和 null 可不是一個含義,萬一你程式出異常了,把鍋甩給我怎麼辦?

算了,我還是拋異常吧,最穩妥了。

所以你看,要是你從這個拋異常的地方去找答案,也許能找到,但是路就走遠了一點。

因為這個地方並不是問題的根因。

到這裡,你應該清楚這個 BUG 到底是怎麼回事了。

request 的生命週期

在探索這個問題的過程中,我也想到了另外一個問題:

一個 request 請求的生命週期是怎麼樣的?

這題我記得幾年前我背過,現在我確實有點想不起來了,但是我知道去哪裡找答案。

Java Servlet Specification,這是一份規範,答案就藏在這個規範裡面:

https://javaee.github.io/servlet-spec/downloads/servlet-4.0/servlet-4_0_FINAL.pdf

在 3.13 小節裡面,關於 request 這個 Object 的生命週期,規範是這樣說的:

這寥寥數語,非常關鍵,所以我一句句的拆解給你看。

Each request object is valid only within the scope of a servlet’s service method, or within the scope of a filter’s doFilter method,unless the asynchronous processing is enabled for the component and the startAsync method is invoked on the request object.

一上來就是一個長句,但是根本不要慌。

你知道的,我英語八級半,水平一向是可以的。

先把長句拆短一點,我可以先只翻譯 unless 之前的部分。

前面這部分說:每個 request 物件只在 servlet 的服務方法的範圍內有效,或者在過濾器的 doFilter 方法的範圍內有效。

接著它來了一個 unless,表示轉折,和 but 差不多。

我們主要關注 unless 後面這句:

the asynchronous processing is enabled for the component and the startAsync method is invoked on the request object.

元件的非同步處理功能被啟用,並且在 request 上呼叫了 startAsync 方法。

也就是說,request 的生命週期在遇到非同步的時候有點特殊,但是這個非同步又不是我前面演示的那種非同步。

關於非同步,規範中提到了 request 裡面有個方法:startAsync。

我去看了一眼,果然是有:

返回值是一個叫做 AsyncContext 的東西。

但是我先按下不表,接著往下翻譯。

In the case where asynchronous processing occurs, the request object remains valid until complete is invoked on the AsyncContext.

在發生非同步處理的情況下,request 物件的生命週期一直會延續到在 AsyncContext 上呼叫 complete 方法之前。

這裡又提到了一個 complete 方法,這個 complete 方法 invoked on the AsyncContext。

AsyncContext 是什麼玩意?

不就是 request.startAsync() 方法的返回值嗎?

果然在 AsyncContext 裡面有個 complete 方法:

不慌,繼續按下不表,一會就回收,接著往下看。

Containers commonly recycle request objects in order to avoid the performance overhead of request object creation.

容器通常會 recycle 請求物件,以避免建立請求物件的效能開銷。

看到這個 recycle 我們就很眼熟了,原來規範裡面是建議了容器裡面實現 request 的時候儘量複用,而不是回收,目的是節約效能。

這玩意,屬於意外收穫呀。

最後一句話是這樣的:

The developer must be aware that maintaining references to request objects for which startAsync has not been called outside the scope described above is not recommended as it may have indeterminate results.

這句話是說:程式設計師朋友們必須要意識到,我不建議在上述範圍之外維護 request 的參照,因為它可能會產生不確定的結果。

看到這個「不確定的結果」時我很開心,因為我前面已經演示過了,確實會產生莫名其妙的結果。

但是規範裡面在「scope」之前還加了一個限定詞:startAsync has not been called。

反過來說,意思就是如果你有一個呼叫了 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 的非同步程式設計相關的知識更加重要,本文只是做了一個小小的引子,如果這塊知識對你是空白的,希望你有興趣的話自己去研究一下,很有價值。

最後,我想說的是,關於之前文章的一個留言:

從看到這個現象,到寫完這篇文章,我不斷的偵錯程式,至少重啟了近百次服務,發起了上百次請求。在原始碼裡面也走了一些彎路,最後才抽絲剝繭的看到本問題的根因。

所以,我排查問題的經驗就一個字:

歡迎關注公眾號【why技術】,文章全網首發。