30丨案例：為什麼引數化資料會導致TPS突然下降
在效能測試中，引數化資料是少有的每個效能測試工程師都會用得到，卻經常出現問題的技術點之一。從我的角度來說，究其原因，大部分是因為對效能引數化資料的理解不足。導致的結果就是用了引數化，但和真實的使用者場景不一致，從而使得整個效能測試場景都失去了意義。
這樣的例子不在少數。
一個專案開始之初，由於沒有歷史沉澱的資料，所以我們需要造一些資料來做效能測試。造多少呢？並不是按未來生產的容量來造，而是按效能場景中需要的資料量級來造。這種錯誤的做法是很多專案中真實出現的事情。
這並不止是效能測試工程師之過，還有很多其他的複雜原因，比如時間不夠；經驗不足，只能造重複的資料等等。
那麼效能測試引數化資料的獲取邏輯到底是什麼呢？我們來看一個圖吧。
在這個圖中，我用不同的顏色表示不同元件中的資料。壓力工具中的引數化資料有兩種，這一點，我們前面有提到過，引數化資料有兩大型別：
- 使用者輸入的資料同時在後臺數據庫中已存在。
- 使用者輸入的資料同時在後臺數據庫中不存在。
當我們使用資料庫中已存在的資料時，就必須考慮到這個資料是否符合真實使用者場景中的資料分佈。當我們使用資料庫中不存在的資料時，就必須考慮輸入是否符合真實使用者的輸入。
在本篇要說的案例中，我們來看一下引數化資料如果做錯了，對效能結果會產生什麼樣的影響。
案例問題描述
在一次壓力測試的過程中，出現瞭如下所示的TPS資料（本篇文章中一些截圖會有些模糊，因為來自於之前專案中的具體案例，在當時截圖時，也並沒有考慮清晰度，不過我們只要看趨勢就好）。
在下圖中，我們可以看到，在壓力測試過程中，出現了TPS陡減到底的情況。這顯然是不合理的。
這個曲線的趨勢把效能瓶頸呈現得非常明顯。在出現這個問題之後，當時我們也嘗試過把執行緒數降低，觀察TPS的趨勢，結果從300到100到50到10，最後到1，發現都會出現這樣的TPS陡減到底的情況，只是時間長度不同而已。
這非常像某個資源因為處理業務量的累積達到了某個臨界點而產生的情形。
但不管怎樣，我們還是要按正常分析的思路來分析它。
分析過程
首先，仍然是畫一個架構圖。
在這個圖中，我們可以看到，JMeter是連線到第一層服務（這裡是有兩個Tomcat例項），再到第二層服務（這裡是也有兩個Tomcat例項），然後再連到DB中。這個DB是一個網際網路金融DB（通過MySQL改造來的）。
瞭解了架構圖之後，現在就開始檢視下效能資料吧。
查作業系統
先看一下作業系統的效能資料：
從top中，我們可以看到這個應用伺服器沒啥壓力，在這樣的狀態中，你可能都不用再去查其他的作業系統資訊了，因為目前的壓力對這個系統來說確實是小了點。
查應用
再看下應用的狀態，這裡用的工具仍然是前文中提到過多次的JvisualVM（請你在用效能監控工具的時候，不要糾結，只要工具好使，用到吐都行，不用跟風）。
從這個圖中可以看到的是，這個應用使用到的CPU確實很低，並且堆也沒用多少。其實在這一步，我查了四個Tomcat的狀態，只是截了一個圖而已。
在這裡還是要囉嗦一下了，對這樣的曲線，我們一定要一眼就能看出問題在哪裡。出現上圖這樣的情況是因為以下兩個原因：
- 應用CPU使用率（橙色CPU線）確實是太低了，才15%左右。這和前面的top也是能對得上的。Java的GC幾乎沒佔CPU（藍色CPU線），也就是說Tomcat在這裡沒壓力。
- 從堆曲線的趨勢上來看，1G的堆才到了400M多一點，並且回收一直都非常正常。怎麼判斷這個“正常”呢？首先，年輕代、年老代回收很有規律，並且沒消耗什麼CPU；其次，每次FullGC都能回到150M左右，非常平穩。可見這個記憶體使用沒啥問題。
當然到了這裡，我當時也是查了網路的，只是也沒什麼壓力，所以沒做具體的記錄（從這點可以看出，如果你在做效能測試的時候，要想記錄效能瓶頸的分析過程，一定要記得把資料記全了，不然以後你可能都想不起來當時做了什麼事情）。
查DB
既然上面都沒啥問題，DB又是一個MySQL，所以這裡，我先手動執行了幾個常規的查詢語句。在DB中檢視如下資訊。
查processlist、innodb_trx、innodb_locks、innodb_lock_waits。在沒有監控工具時，這幾個是我經常在MySQL資料庫檢查的表，因為資料庫如果慢的話，基本上會在這幾個表中留些蛛絲馬跡。
processlist是看當前資料庫中的session的，並且也會把正在執行的SQL列出來，快速重新整理幾次，就可以看到是不是有SQL一直卡在那裡。
innodb_trx是正在執行的SQL事務表，這個表很重要。
innodb_locks和innodb_lock_waits是為了看有沒有鎖等待。
拿一條業務SQL執行一下，看看在壓力之中會不會慢。這是在沒有資料庫監控時，快速判斷業務的方法。因為這個業務很單一，用的SQL也單一，所以我在這裡可以這樣做。執行了之後，並沒有發現業務SQL慢。
由此基本判斷DB沒什麼問題。
注意，判斷到了這裡，其實已經出現了證據不完整產生的方向偏離！
陷入困局之後的手段
更悲催的是這個業務系統的日誌記錄的非常“簡潔”，連時間消耗都沒有記錄下來。想來想去，在這麼簡單的一個架構中，沒什麼可查的東西了吧，除非網路中有裝置導致了這個問題的出現？
在沒有其它監控工具的情況下，當時我們上了最傻最二最基礎又最有效的時間拆分手段：抓包！
抓包其實是個挺需要技巧的活，不止是說你能把包抓出來，還要能分析出來時間消耗在誰那裡。這時我提醒一下，當你學會抓包工具的使用時，不要在每個場景下都想露一手你的抓包能力，通過抓的包分析響應時間的消耗點。
在我的工作中，只有萬般無奈時才會祭出“抓包”這樣的手段，並不是因為我對網路不夠了解。恰恰是因為了解得足夠多的，我才建議不要隨便抓包。因為但凡在應用層有工具可以分析響應時間，都會比抓網路層的包來得更加簡單直觀。
經過一段段的分析之後，在資料庫的一個主機上看到了如下資訊：
看到這裡的TCP segment of a reassembled PDU沒有？它之上是ACK。放大一下，看看這裡的時間：
看到沒有，這裡有兩秒的時間才發資料，那它是在幹嗎呢？
這裡就要說明一下TCP segment of a reassembled PDU了，PDU就是Protocol Data Unit。
以下高能燒腦，不喜可跳過！
它是指在TCP層接收到應用層發的非常大的資料之後，需要將資料大刀闊斧地砍成幾段之後再發出去。就是這個砍資料的過程消耗了2秒的時間。
可是為什麼TCP層要幹這個事呢？上層應用給了你一大塊資料包，你直接往外扔不就行了嗎？還要自己reassemble（重新裝配），費老大勁。
這其實TCP的一個引數來決定的，它就是MSS（Maximum Segment Size）。在TCP一開始打招呼的時候（就是握手的過程），已經通過MSS這個可選項告訴對方自己能接收的最大報文是多少了，這是不加任何資訊的大小，純的。而在乙太網上，這個值是設定為1460位元組的，為啥是1460呢？因為加上TCP頭的20個位元組和IP頭的20個位元組，剛好不大不小1500位元組。
當你看到1500位元組的時候，是不是有一種似曾相識的感覺？它就是現在普遍設定的MTU（Maximum Transmission Unit）的大小呀。
這時你可能會說了，那我可以把MTU設定大嘛。可是你自己設定不行呀，別人（各主機和網路裝置）都得跟著你設定才行，要不然到了MTU不大的地方，還得分包，還是要費時間。
而接收端呢？接資料時接到這些包的ACK序號都是一樣的，但Sequence Number不同，並且後一個Sequence Number是前一個Sequence Number+報文大小的值，那接收端就可以判斷這是一個TCP Segment了。
好了，解釋完這些之後，回到前面的問題。資料庫自己耗時了兩秒來做reassemble PDU。至於嗎？不就是過來查個數據嗎？考慮了一下業務特徵，這就是根據客戶ID查一個帳戶的一個月或三個月的記錄資訊，通常是100條左右，最多也就200條，也不至於有這麼大。但是不管怎麼樣，還是資料庫的問題！
這就是我前面說的查DB的時候，由於證據不全導致了分析思路的偏差。因為我手動執行了這個語句的時候並不慢，只要10幾毫秒，所以，那時候我覺得資料庫不是問題點。
但是經過了抓包之後，發現問題還是出在DB上。有時候真不能那麼自信呀，容易給自己挖坑，要是早把活幹得細緻一點，也不至於要抓包了。
接著分析DB
那我們肯定要接著看DB上的資訊了，既然資料量大，SQL執行得慢，那就先撈出慢日誌看看。
檢視如下負載資訊：
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ================= ===== ======= ===== ==========
# 1 0xB5DEC0207094BA2F 117365.8906 44.9% 14120 8.3120 8.46 SELECT
# 2 0xFF8A1413823E401F 62050.0287 23.7% 12078 5.1374 2.78 SELECT
# 3 0xC861142E667B5663 36004.3209 13.8% 21687 1.6602 0.13 SELECT
# 4 0xFB7DBC1F41799DDD 32413.9030 12.4% 19615 1.6525 0.09 SELECT
# 5 0xC065900AEAC5717F 11056.5444 4.2% 9304 1.1884 0.02 SELECT
# 9 0x6422DFBA813FC194 202.4342 0.1% 54 3.7488 1.83 INSERT
# 11 0x197C9DCF5DB927C8 137.4273 0.1% 36 3.8174 1.14 INSERT
# 13 0x1A9D64E72B53D706 97.9536 0.0% 31 3.1598 2.65 UPDATE
# 36 0x3B44178A8B9CE1C3 20.1134 0.0% 16 1.2571 0.04 INSERT
# 39 0x370753250D9FB9EF 14.5224 0.0% 11 1.3202 0.04 INSERT
# MISC 0xMISC 2152.2442 0.8% 151 14.2533 0.0 <72 ITEMS>
你可以看到確實有四個SQL消耗了更多的時間，並且時間還不短。這是明顯的效能問題，但是我把這SQL拿出來執行過呀，並不慢。
怎麼回事呢？
我讓做資料庫運維的人把DB proxy層的所有SQL日誌拿出來分析一遍。為什麼我要DB proxy層的資料呢？因為這一段會把所有執行的SQL都記錄下來，而慢日誌記錄的是1s以上的（取決於DB中的配置）。首先是把time cost大於200ms的SQL都拉出來，結果發現，真的在TPS下降的那個時間段，出現了SQL執行超長的情況，並且和我執行的，還是同樣的業務SQL。
怎麼辦？既然到這個層面了，這些執行的SQL只有一點區別，那就是查詢條件。慢的SQL的查詢條件，我拿回來試了，果然是慢，查出來的資料也是完全不一樣的，居然能查出幾萬條資料來。前面說了，這個語句是根據客戶ID查出記錄數的，那麼就根據客戶ID，做一次group by，看下資料量為啥有這麼多大差別。
於是得到了如下的結果：
客戶ID, 數量
'這一列只是客戶id，無它', '91307'
'這一列只是客戶id，無它', '69865'
'這一列只是客戶id，無它', '55075'
'這一列只是客戶id，無它', '54990'
'這一列只是客戶id，無它', '54975'
'這一列只是客戶id，無它', '54962'
'這一列只是客戶id，無它', '54899'
'這一列只是客戶id，無它', '54898'
'這一列只是客戶id，無它', '54874'
'這一列只是客戶id，無它', '54862'
....................
'這一列只是客戶id，無它', '161'
'這一列只是客戶id，無它', '161'
'這一列只是客戶id，無它', '161'
'這一列只是客戶id，無它', '161'
'這一列只是客戶id，無它', '161'
'這一列只是客戶id，無它', '161'
'這一列只是客戶id，無它', '160'
'這一列只是客戶id，無它', '160'
從這個結果可以看到，不同客戶ID的記錄條數差別太大了。這是誰幹的好事？！我們一開始就強調資料需要造均衡，要符合生產真實使用者的資料分佈。
到這裡，問題基本上就明確了，查一下引數化的資料，裡面有10萬條資料，而取到記錄數在五六萬左右的客戶ID的時候，才出現了響應時間長的問題。
而我之前的執行的SQL，恰好試了多次都是資料量少的。
下面怎麼辦呢？先做個最規矩的實驗，把5萬條往後的資料全都刪掉！場景再執行一遍。
於是就得到了如下的結果：
問題完美解決。
可是問題怎麼出現的呢？
經過詢問負責產生基礎資料的人，最後得知，一開始資料庫裡的基礎資料不夠。由於我在專案中要求基礎資料量和引數化資料量要達到生產級別。於是把這個工作安排給了一個同事，就是造出每個客戶都和生產環境中差不多量級的記錄。當時是用壓力指令碼做客戶ID的引數化，然後用執行壓力的方式造的資料。
本來這個事情在做的時候，應該是把每個客戶ID都加到差不多的記錄的。但是這個人在做的時候，覺得一個個迴圈加下去實在是太消耗時間了，終於等不急了，於是在幹了幾個小時之後，覺得每個客戶ID上都有了一些資料量之後，自己做了個決定，把客戶ID減少到只有幾百個，這樣很快就幹完了！
哭笑不得的感覺有沒有？！
總結
很多效能問題，在出現的時候，都會覺得無從下手，而當分析到根本原因的時候，就覺得啼笑皆非。
但很多時候，在真實的場景中，很多效能問題連原因都沒有分析出來，連啼笑皆非的機會都沒有，就開始尋找規避的手段了，這就像用一個坑去埋另一個坑，於是大坑套小坑、小坑套水窪。
還有，在做效能分析的時候，有經驗固然是好事，但是經驗也並不是在所有的場景中都能有效地幫你解決問題，相反，它們有時也會成為累贅，成為判斷出現偏差的原因。
所以我現在都會誠心地告誡一些效能測試從業人員：一定要全域性監控、定向監控一層層資料查，不要覺得查了某個點就判斷這個元件沒問題了。像我這樣的老鳥也照樣得從全域性查起，不然也是掉坑裡。而這個“全域性-定向”的思路，也照樣適用一些新手，可以形成排查手冊。