天天看點

LoadRunner腳本日志定位問題案例

本文選自《loadrunner虛拟使用者進階開發指南》一書,該書主要為了loadrunner 使用人員精通腳本開發而創作,目的是分享作者們的經驗,使大家在更短的時間内成為loadrunner 的高手。

本案例來源于一個銀行項目的性能調優階段。

在性能調優過程中發現如下現象:loadrunner 分析報告中的“繳費”等事務響應時間始終比目标測試子產品日志統計到的時間多了200ms 左右。其中,loadrunner 統計了從發出交易封包到傳回執行結果的時間,目标系統則記錄了“從收到loadrunner 封包後進行處理=>發送給其背景子產品處理=>其背景子產品傳回結果=>處理後将執行結果傳回給loadrunner”這一過程的時間。

對于這個問題,依次進行了如下的排查過程。

第一步:首先核實vuser 腳本,确認腳本本身處理過程是否存在性能消耗。分析的重點主要涉及對封包進行的資料處理、傳回結果的分析判斷等代碼是否有問題。為了分析問題将腳本最終簡化成如例4-38 所示,但問題仍然存在。

LoadRunner腳本日志定位問題案例

第二步:分析目标測試子產品的日志記錄環節,确認沒有問題。

第三步:通過監控網絡性能,進一步确認了網絡沒有問題。

上面的幾個常見原因依次排除後,基本可以确定這200ms 應該耗費在loadrunner 與目标測試系統的通信互動過程中,測試團隊需要做的是,深入分析時間具體耗費在哪些互動環節上。

分析這類問題,最重要的手段就是深入分析vuser 腳本的執行日志。打開腳本的“run-time settings”對話框,勾選擴充log 中的“advanced trace”複選框,以打卡執行過程的詳細追蹤。注意擴充log 中的其他選項不要勾選,否則日志輸出較多的情況下閱讀起來較麻煩,不容易定位問題。

腳本執行完成後,接下來開始分析執行日志來查找問題。為了便于講解,下面分别列出了發送和接收過程的日志。發送過程日志如下:

LoadRunner腳本日志定位問題案例
LoadRunner腳本日志定位問題案例
LoadRunner腳本日志定位問題案例

可以看到,從15:45:29.148 開始讀取buf0,15:45:29.226 完成發送,總共耗時78ms。是以可以判斷多消耗的200ms 不可能耗費在發送環節上,進而可以初步斷定問題很有可能出在接收封包的環節上。接收過程日志如下:

我們詳細分析一下上面的接收過程日志。

15:45:29.288: 準備從socket0 讀取542 位元組。

15:45:29.319: 準備首次從socket 讀取資料,逾時設定為10s。

15:45:29.538: 準備讀取8192 個位元組。

15:45:29.584: 存儲讀取到的9 個位元組。

15:45:29.600: 未接收到指定長度資料,按照逾時設定10s 繼續等待。

15:45:29.756: 準備讀取8192 個位元組。

15:45:29.787: 存儲讀取到的651 個位元組。

15:45:29.818: 未接收到指定長度資料,按照逾時設定10s 繼續等待。

15:45:29.850: 準備讀取8192 個位元組。

接收完成,接收長度不比對(期望 542 位元組,實際收到 660 位元組,相差118 個位元組)。

……

在上面的封包接收過程中,可以看到一共進行了3 次接收資料操作:第一次接收了9個位元組;第二次接收了651 個位元組;第三次接收時socket 已經關閉是以完成了接收。需要引起注意的是,前兩次接收的時候相差時間為15:45:29.787-15:45:29.584=203ms。這203ms是很有可能就是loadrunner 統計時間與應用程式日志統計結果的偏差。

兩次接收時間相差了203ms,這不是正常情況下的網絡延遲時間。是以,可以初步懷疑應用程式是分了兩次來發送封包:第一次發送了封包頭;第二次發送了封包體;之後斷開了socket 連接配接,是以看到了vuser 第三次接收封包時沒有收到任何内容,并完成接收封包函數的執行。

為了驗證上面的假設,先修改一下接收資料過程的逾時時間設定,将預設的10s 修改為0.1ms(逾時設定應該小于200ms,這樣可以隻接收到第一次發送的封包頭,進而确認每次接收封包過程中形成的接收等待時間是有規律的)。

具體操作為在事務開始前增加語句“lrs_set_recv_timeout2(0,100000);”,修改的腳本如例4-39 所示。

LoadRunner腳本日志定位問題案例

回放腳本, 部分執行日志如下:

LoadRunner腳本日志定位問題案例
LoadRunner腳本日志定位問題案例

在上面的日志中可以看到加入逾時設定後,可以看到本次共接收了9 位元組,基本可以斷定應用程式傳回封包分兩次發送。接下來繼續通過實驗驗證結論:增加一次接收過程來确認是因為應用程式分兩次發送封包形成的時間間隔導緻浪費了200ms。

修改後的腳本如例4-40 所示。

LoadRunner腳本日志定位問題案例

例4-40 中,第二次接收過程“lrs_receive("socket0", "buf2", lrslastarg);”語句對應執行日志如下:

LoadRunner腳本日志定位問題案例

在上面的日志中可以看到第二次接收函數執行時能夠成功接收到資料,接收完成後socket 關閉。這時已經可以完全确定應用程式傳回交易執行結果過程如下:第一步發送封包頭;第二步發送封包體;第三步關閉socket 連接配接。通過與開發團隊進行反複溝通與确認,證明了測試小組的結論。

在應用程式将兩次發送封包合并成一次發送後,loadrunner 統計結果與應用程式統計結果基本一緻。到這一步終于完成了對應用程式底層代碼的調優,使大部分交易性能均提高了200ms 以上。

本文選自《loadrunner虛拟使用者進階開發指南》一書。

LoadRunner腳本日志定位問題案例

繼續閱讀