K6 壓測練習 - 挑戰網站極限,逼出 HTTP 503
1 |
前幾天介紹壓力測試工具 K6時,提到效能測試可再細分煙霧測試、負載測試、壓力測試... 等,其中壓力測試(Stress Testing)是測試系統在高度負載或極端條件下的穩定性及可靠度,目的在找出系統極限。
大家應該知道或看過,遇到流量過大,網站資源不足以應付 HTTP 請求時會拋出 HTTP 503 Server Unavailable 回應,直接擋掉超量無法消化的請求。這可視為一種保護機制,避免源源不絕的請求讓系統完全崩潰,盡可能保留資源將一部分請求處理完。(註:伺服器超載會導致 HTTP 503,但 HTTP 503 未必是超載引起,也可能是程序掛點、系統當機或其他原因)
生活案例 五月天2018「人生無限公司」演唱會,最終回至台中舉辦,在9月30日上午11點進行賣票,粉絲全都嚴陣以待,就是想搶到一張票,結果擠爆拓元的售票系統,網頁狂轉圈圈接著整個崩壞,只剩下「ERROR 503」,甚至有網友說才30秒網頁就全部當機,讓粉絲全都崩潰,約15分鐘後網頁才恢復正常,讓粉絲順利買票。
在這篇文章,我打算寫一段 K6 壓力測試腳本,測試某個掛在 IIS 的 ASP.NET Core WebAPI 最高可以承受多大流量,在什麼情況下開始噴出 HTTP 503,並實地觀察系統過載後會發生什麼事。
先介紹本次使用的靶機,VM 配備為 AMD EPYC 7452 16 核 vCPU + 64GB RAM,OS 為 Windows 2022,網站為 ASP.NET Core 7.0,測試 WebAPI Action 程式如下,不串 DB 或其他邏輯以免被卡住形成瓶頸,純粹就只是用 JSON 接入物件並傳回簡單回應,無對外 IO 等待,估計大部分的負擔會用在 JSON 反序列化及序列化,流量大時以吃 CPU 運算力為主。本次實驗目的在觀察過載後行為,不比較硬體性能或程式寫法效率,也不做調校改良,故上述部分非重點,就簡單帶過:
[HttpPost]
[Route(nameof(TestJson))]
public IActionResult TestJson(RegisterRequest req)
{
try
{
return Ok(new RegisterResponse
{
LotteryUid = req.LotteryUid,
RespSign = "OK"
});
}
catch (Exception ex)
{
return StatusCode(StatusCodes.Status500InternalServerError, new
{
message = ex.ToString()
});
}
}
要做壓力測試,K6 官網有範例及說明可參考,要用到 ramping-arrival-rate 執行模式,目前是產生每秒固定次數的請求量,並設定 stage 排程逐步加壓,例如:先用 30 秒由 0 增加到每秒發 100 次請求,維持 30 秒後再花 30 秒增加到 200 請求/秒... 以此類推。為了確保有夠多的 Virutal User (可想成平行處理的 Thread) 在一秒內發出指定數量的請求,需指定 preAllocatedVUs 一開始先建好 Thread 備用。更多說明可參考官方文件。
我想將結果繪製成線圖並找出開始出現 503 的時點,K6 可搭配一些套件或服務提供圖形化檢視,如果不嫌麻煩,安裝並串接 InfluxDB + Grafana 後可使用現成的精美圖表工具,是不錯的解決方案。但這次我選擇自己動手寫程式處理,一來不不用再安裝軟體(即使可用 Docker,還是笨重),二則想多了解 K6 細節累積經驗,未來遇到刁鑽客製需求也不用害怕。
K6 執行時,最後會顯示完整統計數字,但是以整個測試過程為範圍,無法看出壓力上升過程的變化;輸出訊息有連線失敗的記錄(下圖 WARN 黃字),但僅限 TCP 連線失敗無回應,不包含 500、503 等 HTTP 回應:
要畫出不同期間的線圖及找出 HTTP 503 時點,需走另一條路 - K6 測試同時也可即時輸出測試歷程到 CSV/JSON 或串接 Elasticsearch、Amazon CloudWatch、Kafka... 等第三方服務),資料細到每個 HTTP 請求各階段的耗時(還細分為發送、TLS 交握、接收... 方便進階分析)、回應檢查結果... 等,再配合自訂 Tag,理論上可實現各式自訂進階解析:
串流寫入 JSON 的 HTTP 請求記錄,跟 IIS 一樣是在取得回應結果時才寫入,故 time 欄位是寫入 JSON 檔的時間,要扣去 http_req_duration 才是 HTTP 送出時間,為了省去計算並精確掌握時間,我加了一個 timestamp 自訂 Tag 記錄發送時間;由於我還想知道記錄當時所處 Stage,是在上升期、穩定期以及目標流量(Arrival Rate),我引用 jslib/utils 的 getCurrentStageIndex() 及 tagWithCurrentStageProfile() 拼湊出 Stage 資訊方便解析。另外,我透過指定 systemTags 參數只保留 'status','error','vu','iter' 四種資料讓資料量小一點。(註:vu + iter 可組出每個請求的唯一鍵值,但這次分析沒用到)
Stage 部分我設定成 5s 增加到 50、維持 5s、用 5s 增加到 100、維持 5s、用 5s 增加到 150、維持 5s... 等遞增設計,預計 70 秒時達到每秒 700 發最高峰。程式如下:
import http from 'k6/http';
import { sleep, check } from 'k6';
import { getCurrentStageIndex, tagWithCurrentStageProfile } from 'https://jslib.k6.io/k6-utils/1.3.0/index.js';
const host = __ENV.HOST || 'http://10.8.0.6';
const mode = __ENV.MODE || 'json';
const stages = [];
for (let t = 50; t <= 700; t += 50) {
stages.push({ duration: '5s', target: t }, { duration: '5s', target: t });
}
export let options = {
systemTags: ['status','error','vu','iter'],
scenarios: {
stress: {
executor: 'ramping-arrival-rate',
preAllocatedVUs: 10000,
timeUnit: "1s",
stages: stages
}
}
};
const jsonPayload = `{
"LotteryUid":"b1a2bef2-0951-48c1-b97b-4a8988447c15",
"SoldTime":"2023-04-04T23:58:44.287528+08:00",
"RetailerId":"0000",
"Numbers":"AQgCAwUN",
"MegaNumber":7,
"ReqSign":"jcGK37pXuW9bGTKJ7/bmDSTuROx3TY/H31USgGtRfkc7pYFkFDoNg9XwJc7g9dUSBSEOWK7WCDJMDL8VlEn8OBttFTVgDc9nTPZpASdUawFJXhmLRgb7AVG5iWNsbxAAaDLW5yDEOEjzWsMpA5dukMJN6RHUUHfuVkux60nE240="
}`;
export default function() {
tagWithCurrentStageProfile();
let res = http.post(`${host}/Registration/TestJson`, jsonPayload, {
tags: {
timestamp: new Date().toISOString(),
target: stages[getCurrentStageIndex()].target
},
headers: { 'Content-Type': 'application/json' }
});
check(res, {
'status is 200': (r) => r.status === 200
});
}
另外,在 IIS 伺服器主機上我用 typeperf 設定每秒記錄一次 CPU、RAM 跟磁碟效能數字存成 Tab 分隔文字檔(TSV)(typeperf -cf counters.txt -sc 300 -si 1 -f TSV -o perf.log
),方便併入測試數據,以對照多大流量時 CPU 衝多高。
測試完畢,我拿到 JSON 及 TSV 檔,用一小段 C# 程式解析統計並轉為 CSV:
using System.ComponentModel;
using System.Text.Json;
using System.Text.Json.Nodes;
var perfData = File.ReadAllLines("perf.log").Skip(1)
.ToDictionary(
o => DateTime.Parse(o.Split('\t').First().Trim('\"')).ToString("HH:mm:ss"),
o => string.Join(",",
o.Split('\t').Skip(1).Select(s => Convert.ToInt32(float.Parse(s.Trim('\"')))).ToArray()));
var iterationLines = File.ReadAllLines("result.json")
.SkipWhile(o => !o.StartsWith("{\"metric\":\"iterations"));
var stats = new Dictionary<int, StatsPoint>();
foreach (string line in iterationLines)
{
var item = JsonObject.Parse(line);
var metric = item["metric"].GetValue<string>();
if (metric != "http_req_duration") continue;
var data = item["data"].AsObject();
var logTime = data["time"].GetValue<DateTime>();
var val = Convert.ToInt32(data["value"].GetValue<float>());
var tags = data["tags"].AsObject();
var startTime = tags["timestamp"].GetValue<DateTime>();
var status = tags["status"].GetValue<string>();
var stageProfile = tags["stage_profile"].GetValue<string>();
var target = tags["target"].GetValue<string>();
if (StatsPoint.StartTime == DateTime.MinValue)
StatsPoint.StartTime = startTime;
var secs = Convert.ToInt32((logTime - StatsPoint.StartTime).TotalSeconds);
if (!stats.ContainsKey(secs)) stats.Add(secs, new StatsPoint { Time = secs });
stats[secs].ReqSent++;
stats[secs].Stage = stageProfile == "steady" ? target : $"~{target}";
var doneSecs = secs + Convert.ToInt32(val / 1000);
if (!stats.ContainsKey(doneSecs)) stats.Add(doneSecs, new StatsPoint { Time = doneSecs });
if (status == "200")
{
stats[doneSecs].ReqDone++;
stats[doneSecs].DoneDura += val;
}
else
{
stats[doneSecs].FailedDura += val;
stats[doneSecs].ReqFailed++;
if (!stats[doneSecs].ErrCodes.ContainsKey(status))
stats[doneSecs].ErrCodes.Add(status, 1);
else
stats[doneSecs].ErrCodes[status]++;
}
}
Console.WriteLine(
"Time,Secs,Stage,ReqSent,ReqDone,ReqFailed,AvgDoneDura,AvgFailedDura,AvgDura,ErrCodeStats,Cpu,Mem,Disk");
foreach (var time in stats.Keys.OrderBy(o => o))
{
var stat = stats[time];
Console.WriteLine(string.Join(",", new string[]
{
stat.LogTime, stat.TimeSpan.ToString("mm\\:ss"), stat.Stage,
stat.ReqSent.ToString(), stat.ReqDone.ToString(), stat.ReqFailed.ToString(),
stat.AvgDoneDura.ToString(), stat.AvgFailedDura.ToString(), stat.AvgDura.ToString(),
stat.ErrCodeStats,
perfData.ContainsKey(stat.LogTime) ? perfData[stat.LogTime] : ",,"
}));
}
public class StatsPoint
{
public static DateTime StartTime = DateTime.MinValue;
public int Time { get; set; }
public TimeSpan TimeSpan => TimeSpan.FromSeconds(Time);
public string LogTime => StartTime.AddSeconds(Time).ToLocalTime().ToString("HH:mm:ss");
public string Stage { get; set; }
public int ReqSent { get; set; }
public int ReqDone { get; set; }
public int ReqFailed { get; set; }
public Dictionary<string, int> ErrCodes = new Dictionary<string, int>();
public string ErrCodeStats => string.Join("|", ErrCodes.Select(o => $"{o.Key}:{o.Value}"));
public int ReqExec => ReqDone + ReqFailed;
public long DoneDura { get; set; }
public long FailedDura { get; set; }
public long TotalDuration => DoneDura + FailedDura;
public int AvgDura => ReqExec > 0 ? Convert.ToInt32(TotalDuration / ReqExec) : 0;
public int AvgDoneDura => ReqDone > 0 ? Convert.ToInt32(DoneDura / ReqDone) : 0;
public int AvgFailedDura => ReqFailed > 0 ? Convert.ToInt32(FailedDura / ReqFailed) : 0;
}
CSV 欄位包含 Time(時間),Secs(執行秒數),Stage(目標請求量/秋),ReqSent(K6 實現送出量/秒),ReqDone(成功回應數/秒),ReqFailed(失敗回應數/秒),AvgDoneDura(成功平均耗時),AvgFailedDura(失敗平均耗時),AvgDura(總平均耗時),ErrCodeStats(失敗碼統計),Cpu,Mem,Disk。使用 Excel 開啟並畫出圖表,薑薑薑薑~~~ 網站在高流量下的成績單出來了:
灰線是目標每秒請求量,橘線是實際送出的請求數,綠色是成功回應數、紅色是失敗回應數,由圖表我得到以下結論:
- 流量達到每秒 300 發之前,橘線都緊跟灰線一起爬升。大約到 300 左右,橘線便卡住升不上去,直到 1:41 左右忽然解禁追上灰線。
原因是 1:41 左右出現大量 503 形成的紅線波形,大致吻合橘線波形。背後狀況應為發出請求後瞬間得到 503 回應,不佔用 TCP 連線及 CPU 資源,故能快速處理下一筆請求。 - 目前的硬體跟系統架構,每秒處理 300 個請求應是極限,綠線從頭到尾頂點在 300 左右,而這呼應 1:00 左右 CPU 藍線達到 100%,可知每秒處理 300 個請求會讓 16 核 CPU 滿載,達到該系統的極限。
- CPU 滿載時,1:05 ~ 2:13 每秒成功處理數出現一向下驟降再回升的波形,開始由 300 跌至 150 再回升,當回傳 503 後,下跌低點來到 100 甚至 50。
- 0:57 ~ 1:40 這段期間,實際送出的請求數低於目標值,推測跟伺服器 CPU 100% 有關,感覺建立連線有困難,這個狀況直到 IIS 啟動 503 保護才改善。
至於 HTTP 503 發生時機,在 1:00 CPU 滿載後,即零星出現 wsarecv: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond. 錯誤(下圖黃標處),但中間有約 40 秒的間隔,直到 1:41 才大量爆出 503 (紅標處)。
為了確認橘線跟不上灰線是因為伺服器端 CPU 滿載造成,我將 VM 升級到 32 核(vCPU),並將測試數量拉高到 1500,再做了一次測試:
這回觀察到類似的線形,但發生時間點及數值不同。CPU 加倍後 (16 增加到 32),成功回應數上限也翻倍由 300 升到近 700;2:12 左右 CPU 100%,橘線開始跟不上灰色目標線,2:56 左右開始出現大量 503,但不像前次平穩地把橘線推高,紅線呈現一波一波的尖峰週期,這部分行為與 16 核不太相同。令人驚奇的是,堆積的請求一次處理完,甚至出現一秒內收到近 1800 筆回應的記錄(4:06 左右),但此階段該被視為失控狀況,不能當成有效的效能數字。因此可知,突破系統效能上限後的表現難以事先推算,變數太多,恐怕還是得實際測過才準。
以往對伺服器過載噴 503 的行為只有模糊概念,這次親手完實驗,觀察到實際行為長了見識,滿足。
This article demonstrates a K6 stress testing example that measures a website's response under high pressure and observes the behavior of the system when it exceeds the load and responds with HTTP 503 responses.
Comments
# by Sam
輸出 CSV 格式結果的方式有個小問題,就是時間不夠精準,它的時間是 unix timestamp (例如 1595325560,轉成 DateTime: 2022-11-29T13:04:35.00+08:00),而 JSON 的時間就詳細很多 (例如2017-05-09T14:34:45.625742514+02:00)。如果每秒測試次數夠多,CSV 會出現時間一樣的情況,用 CSV 結果繪圖時會需要注意一下。