IIS 伺服器過載 Log 分析與現場還原

2023-04-23 06:36 PM

前陣子分享過用 K6 跑壓力測試逼 IIS 噴出 HTTP 503，也展示如何從壓測到產出報表一氣喝成的壓力測試結果圖表自動化工具。前幾天跟同事討論被提醒 - 壓力測試畢竟是備戰演習沙盤推演，正式網站被塞爆噴 503 的案例才是最真實的情境，當下的數據更值得分析研究，更具參考價值。

圖片來源

有道理，我想起星際效應裡，布蘭德教授的重力方程式最終是靠塔斯進入黑洞蒐集到的量子資料才解開...

仔細想想，壓力測試結果解析背後的工作其實是統計每個 Request 的送出時間、回傳時間、HTTP 狀態代碼以及耗用時間，而這些資訊全部都能在 IIS Log 找到。

IIS Log 預設欄位為：date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs(User-Agent) cs(Referer) sc-status sc-substatus sc-win32-status time-taken。要分析統承受壓力與效能表現，只需要以下欄位：參考

date - 日期(UTC)
time - 時間(UTC)，寫入 Log 的時間，傳完回應才寫入
cs-method - 方法：GET、POST... 等
cs-uri-stem - URL 路徑(不含 ? 之後的查詢字串)
sc-status - HTTP 狀態碼，200、500、503...
time-taken - 處理該請求所耗費時間註：收到第一個 Byte 到送完回應為止，IIS 7.0+ 還包含網路傳輸時間，延伸至 Client 回覆收到(Acknowlege)或重設網路連線為止參考

time 是送出回應時間、用 sc-status 200 或 503 來判斷正常或失敗、time-taken 是伺服器處理時間，time - time-taken 可推算客戶端送出請求的時間(不含中間傳輸耗時，但一般可忽略)。有了些數據，我們便能畫出類似 K6 壓測結果的圖表，知道某個時間點每秒有多少個 HTTP 請求流入(Arrival Rate)，IIS 消化並回應掉幾個，何時出現幾次 503 或 500 等錯誤... ，繪製如壓測報表的曲線圖。

我把這個分析工具命名為 iis-burnout-chart / IIS 過勞圖表 XD

程式採 CLI 方式操作，選項及參數使用 System.CommandLine 程式庫實做以符合 POSIX 參數語法慣例。分析 IIS Log 產製圖表標準流程如下：

解讀 IIS Log，產生每秒統計資料檔

# 取得發生 IIS 503 伺服器過載事故當日的 IIS Log 檔，如：u_ex20230423.txt
# 分析指定 Log 的特定 URL 資料
iis-burnout-chart parse -p /Registration/TestJson x:\logs\u_ex20230423.txt
# 或是將 Log 放在 iis-burnout-chart.exe 同目錄，程式會抓日期最新的一筆，另外也可指定 Method，限定 GET 或 POST
iis-burnout-chart parse -p /Registration/Register -m POST
# 分析結果會存為同名 .json，如 u_ex20230423.json，或者也可用 --output 或 -o 指定寫入檔案
# URL 路徑篩選規則採用 Regular Expression 語法以確保夠彈性
iis-burnout-chart parse -p "(?i)/Registration/(TestJson|Register)" -o online-store-crash.json

若不確定過載事故發生時間，可先預覽每小時、每分鐘、每秒統計數字，找出精確時間點。
預設讀取同目錄下日期最新的 JSON 檔，並顯示每分鐘統計：(亦可指定檔名，例如 iis-burn-out preview oops.json)

或者也可先用 -uh 指定以小時為單位統計，先鎖定事故發生在哪一個小時，再用 -s "HH:mm:ss" -e "HH:mm:ss" 參數縮小範圍看每分鐘、每秒鐘統計：
鎖定過載事故的明確起迄時間，繪製圖表
指令為 iis-burnout-chart chart -s 17:01:56 -e 17:05:09，以下是某次壓測 IIS Log 的結果圖表：