在性能測試中,參數化數據是少有的每個性能測試工程師都會用得到,卻經常出現問題的技術點之一。從我的角度來說,究其原因,大部分是因為對性能參數化數據的理解不足。導致的結果就是用了參數化,但和真實的用戶場景不一致,從而使得整個性能測試場景都失去了意義。
這樣的例子不在少數。
一個項目開始之初,由於沒有歷史沉淀的數據,所以我們需要造一些數據來做性能測試。造多少呢?並不是按未來生產的容量來造,而是按性能場景中需要的數據量級來造。這種錯誤的做法是很多項目中真實出現的事情。
這並不止是性能測試工程師之過,還有很多其他的復雜原因,比如時間不夠;經驗不足,只能造重復的數據等等。
那么性能測試參數化數據的獲取邏輯到底是什么呢?我們來看一個圖吧。
在這個圖中,我用不同的顏色表示不同組件中的數據。壓力工具中的參數化數據有兩種,這一點,我們前面有提到過,參數化數據有兩大類型:
- 用戶輸入的數據同時在后台數據庫中已存在。
- 用戶輸入的數據同時在后台數據庫中不存在。
當我們使用數據庫中已存在的數據時,就必須考慮到這個數據是否符合真實用戶場景中的數據分布。當我們使用數據庫中不存在的數據時,就必須考慮輸入是否符合真實用戶的輸入。
在本篇要說的案例中,我們來看一下參數化數據如果做錯了,對性能結果會產生什么樣的影響。
案例問題描述
在一次壓力測試的過程中,出現了如下所示的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減少到只有幾百個,這樣很快就干完了!
哭笑不得的感覺有沒有?!
總結
很多性能問題,在出現的時候,都會覺得無從下手,而當分析到根本原因的時候,就覺得啼笑皆非。
但很多時候,在真實的場景中,很多性能問題連原因都沒有分析出來,連啼笑皆非的機會都沒有,就開始尋找規避的手段了,這就像用一個坑去埋另一個坑,於是大坑套小坑、小坑套水窪。
還有,在做性能分析的時候,有經驗固然是好事,但是經驗也並不是在所有的場景中都能有效地幫你解決問題,相反,它們有時也會成為累贅,成為判斷出現偏差的原因。
所以我現在都會誠心地告誡一些性能測試從業人員:一定要全局監控、定向監控一層層數據查,不要覺得查了某個點就判斷這個組件沒問題了。像我這樣的老鳥也照樣得從全局查起,不然也是掉坑里。而這個“全局-定向”的思路,也照樣適用一些新手,可以形成排查手冊。