K6 壓測練習 - 挑戰網站極限，逼出 HTTP 503

前幾天介紹壓力測試工具 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.