前幾天介紹壓力測試工具 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 結果繪圖時會需要注意一下。

Post a comment