我以為福建移動BOSS系統做的一個小規模的性能測試為例，談談我在數據分析中的一些經驗。測試用例，模式如下圖。 一臺Linux模擬Browser（簡稱browser）向主機SUN發 HTTP請求，SUN上啟動Apache Web Server將請求交給FCGI程序。FCGI程序作為TE節點CC1（簡稱fcgi）的客戶進程發起TE事務，經GT1名字服務向CC2 （簡稱svr_cc）發送一個分支，CC2 上服務嵌套經GT1名字服務向ACCTFZ（在HP上，簡稱svr_ac）發送一個分支。 測試3種壓力情況，即10browser/10fcgi/5svr_cc服務進程/2svr_ac服務進程，20browser/20fcgi/10svr_cc服務進程/2svr_ac服務進程，30browser/20fcgi/10svr_cc服務進程/2svr_ac服務進程。 一．記錄數據。 各個部分的應用程序在程序中關鍵地方記錄時間，精確到微秒（毫秒也可以），并按一定格式寫入日志文件。這樣可以并計算相同應用相臨時間點之間的平均時間差（編程序分析日志文件或用excel導入）。有了時間差，才能分析出整個系統性能的瓶頸（處理慢的環節）。下面給出一個fcgi進程（也是TE客戶端進程）的日志文件片段。 [19:21:32.628.512] begin_tpbegin [19:21:32.628.833] end_tpbegin [19:21:32.628.944] begin_tpsetbranch [19:21:32.629.053] end_tpsetbranch [19:21:32.629.487] begin_tpcall [19:21:37.102.996] end_tpcall [19:21:37.103.806] begin_tpcommit [19:21:37.432.253] end_tpcommit [19:21:40.405.345] begin_tpbegin [19:21:40.405.532] end_tpbegin [19:21:40.405.639] begin_tpsetbranch [19:21:40.405.742] end_tpsetbranch [19:21:40.406.175] begin_tpcall [19:21:46.732.888] end_tpcall [19:21:46.733.650] begin_tpcommit [19:21:46.832.538] end_tpcommit 第一個字段是時間點時間，第二個字段是該時間點描述串，兩個字段用空格間隔。從這個文件可以看出，fcgi進程是循環處理業務的。begin_tpbegin處開始一筆業務，begin_tpcall和end_tpcall之間是TE_tpcall()發起請求到收到應答的時間，begin_tpbegin和end_tpbegin之間是TE_tpcommit()發起提交到收到提交應答的時間。而end_tpcommit到begin_tpcall是fcgi進程從一筆業務結束到開始下一筆業務的時間，在這里也就是fcgi進程從Web Server獲取HTTP請求的時間。 從這種格式的原始數據文件可以編程序計算出相臨時間點之間的時間差，并可以計算出所有交易的平均時間差。也可以用excel打開這種格式的原始數據文件，按空格分隔各列，讀入excel后就可以使用excel提供的函數（入SEC()函數從hh:mm:ss時間格式換算成秒）和公式計算時間差和平均值，以及產生圖表等等。事實證明excel的功能是十分強大和方便的。 二．誤差的判斷和排除。 根據原始數據統計出的3種壓力情況下fcgi各點時間如下。
比較10_10_5_2和20_20_10_2，由于20_20_10_2在SUN主機上啟動fcgi進程和svr_cc服務進程數都比10_10_5_2多，SUN上的壓力也較大，因此receive from fcgi的時間也較大是合理的。比較20_20_10_2和30_20_10_2，2在SUN主機上，壓力沒有變化，僅是有HTTP請求的排隊（因為browser進程比fcgi進程多），SUN上的壓力應基本一樣，而receive from fcgi的時間有較大的差別是不合理的�？紤]到在測30_20_10_2并發時有失敗業務，懷疑可能由于browser上加給web Server過大造成失敗。這次性能測試主要測試系統正常（業務正常，壓力情況是預計壓力情況）時的系統情況，而在有業務失敗時往往有些前端進程工作不正常，不能對后臺造成預期的壓力，這時取平均值可能會造成較大誤差。 拿出其中任一個FCGI進程的原始數據，比較其在20_20_10_2和30_20_10_2兩種壓力下的receive from fcgi的時間數據，并用excel產生圖表，  入下圖。  比較上面兩個圖表可以發現，20_20_10_2時各時間點基本都平均分布在1.5秒之內，僅有極少數幾個點在1.5秒之外，且最大不超過4秒，由此可以認為對這些值取平均值的誤差是可以接受的。而30_20_10_2時在測試開始階段（800筆之前）和結束階段（4500筆之后）的時間點明顯高于中間階段的時間點，這應該是由于壓力大時在測試開始階段30個browser進程沒有很快把壓力壓向fcgi（壓力小時也有這種情況，但時間會小的多），這樣造成30個browser進程也不是在相近時間內結束，在結束階段只有少數browser進程仍沒有完成，這時的系統壓力變小，fcgi進程等待HTTP請求時間也變長。在30_20_10_2時這種非正常壓力時間段很長并且數據差距很大，這時取全部時間段內的數值的平均值必然帶來誤差。從上圖可以看到，應該取800筆到4500之間系統穩定時的數據作為有效數據。注意其他環節的進程的時間統計也需要按這一筆數范圍作為有效數據。經過修正后的全部數據見下表。數據基本正常。
經驗：有時取平均值會有較大的誤差，尤其是測試不完全正常的情況。這時需要仔細分析原始數據，排除造成誤差的數據，以系統穩定（正常）時的數據作為有效數據。這里excel圖表功能是一個非常好用的工具。 三．數據分析。 從業務流程中可以想象，fcgi端的TE_tpcall()時間似乎應該大致等于或略大于（網絡傳輸時間等等）svr_cc上服務總的時間加上排隊時間，而排隊時間應該這樣線性計算：前端并發數/服務端并發數*服務端服務單筆總的平均時間。但上表的實際數據是TE_tpcall()時間小于svr_cc上服務總的時間！類似的，browser端的時間和fcgi上fcgi進程處理時間也有這種現象，只是相差很小。 這是因為實際情況不是我們想象的那樣！SUN主機上即有客戶端cc1（包括FCGI）節點也有服務端cc2節點的進程和TE核心運行。如果cc1上只有一個fcgi進程（TE客戶端進程）串行發起業務，我們可以認為fcgi端的TE_tpcall()時間似乎應該大致等于或略大于（網絡傳輸時間等等）svr_cc上服務總的時間。而當cc1上有多個fcgi進程（TE客戶端進程）并發發起業務時，在處理一筆服務業務邏輯的時間段內，SUN上的CPU時間還會分給其他客戶進程以及TE核心（處理其他事務），這樣在客戶端并發情況下，每筆業務的服務端處理時間實際上包含一部分其他筆業務（客戶進程和TE核心）的處理時間里。而所有的業務都是如此，最終TE_tpcall()平均時間小于svr_cc上服務總的平均時間。 在cc1進程和cc2進程的關系中，由于他們在一臺主機上，并且cc1進程不在少數，因此上述兩個時間差別也較大。而在browser和cc1的關系中，可以排除客戶端進程的處理（因為在另外一臺機器上）對服務端的影響，而只有TE核心并行處理多個交易對單筆服務處理時間的影響。在測試環境下，服務業務處理時間是主要時間，TE處理時間相對很小，因此上述兩個時間差別也非常小。 經驗：在多前端并發情況下，前端等待服務端應答時間和服務端處理時間不是線性比例關系，會比預期線性比例關系算出的時間小。具體差別和測試環境配置有關系�？蛻舳撕头⻊斩朔珠_在不同的機器上會更接近線性比例關系。 四．平均值以外的東西。 對測試原始數據取平均值可以對整個系統的性能有一個了解，但有時只看平均值會遺漏一些同樣有價值的東西。 取30_20_10_2測試中任一個svr_cc服務進程的原始數據，用excel讀入，計算每筆service_before_tpcall時間（該服務的主要業務邏輯時間，也是整個開戶業務中最耗時間的環節），并制作service_before_tpcall時間隨筆數變化的圖表，我們可以看到服務業務邏輯隨數據庫中記錄數的變化規律，這顯然是平均值無法體現的。 從圖中可以看出，該業務邏輯時間的平均分布隨筆數的增加而增加，也就是說，該業務邏輯時間和數據庫中記錄數有關（因為開戶是插入操作，應該是該業務邏輯時間的平均分布隨數據庫記錄數的增加而增加），在這種大型OLTP系統中，這種處理時間和數據庫記錄數有較大關系的現象是不好的。一般是因為數據庫索引設置問題，需要調整數據庫索引。  至于最后幾十筆的時間急劇減小，是因為在最后幾十筆時有些前端應用已經完成，對于后臺的壓力減小，服務處理時間自然減小，并且越到后來運行的前端應用越少，服務處理時間也越少。結合前面第二節的經驗，在這個例子中，因為這些無效數據只占全部數據很少一部分，它們不會對平均值產生太大的誤差。 經驗：有時平均值數據不能反映系統全部特性。尤其對于系統關鍵環節，必要時還對原始數據做進一步統計分析。 |
延伸閱讀
文章來源于領測軟件測試網 http://www.kjueaiud.com/
