6

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

 1 year ago
source link: https://blog.darkthread.net/blog/stress-test-by-k6/
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
neoserver,ios ssh client

挑戰網站極限,逼出 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 回應:

Fig1_638165982644805824.png

要畫出不同期間的線圖及找出 HTTP 503 時點,需走另一條路 - K6 測試同時也可即時輸出測試歷程到 CSV/JSON 或串接 Elasticsearch、Amazon CloudWatch、Kafka... 等第三方服務),資料細到每個 HTTP 請求各階段的耗時(還細分為發送、TLS 交握、接收... 方便進階分析)、回應檢查結果... 等,再配合自訂 Tag,理論上可實現各式自訂進階解析:

Fig2_638165982647015024.png

串流寫入 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 開啟並畫出圖表,薑薑薑薑~~~ 網站在高流量下的成績單出來了:

Fig3_638165982648900923.png

灰線是目標每秒請求量,橘線是實際送出的請求數,綠色是成功回應數、紅色是失敗回應數,由圖表我得到以下結論:

  • 流量達到每秒 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 (紅標處)。

Fig4_638165982650973906.png

為了確認橘線跟不上灰線是因為伺服器端 CPU 滿載造成,我將 VM 升級到 32 核(vCPU),並將測試數量拉高到 1500,再做了一次測試:

Fig5_638165982652902668.png

這回觀察到類似的線形,但發生時間點及數值不同。CPU 加倍後 (16 增加到 32),成功回應數上限也翻倍由 300 升到近 700;2:12 左右 CPU 100%,橘線開始跟不上灰色目標線,2:56 左右開始出現大量 503,但不像前次平穩地把橘線推高,紅線呈現一波一波的尖峰週期,這部分行為與 16 核不太相同。令人驚奇的是,堆積的請求一次處理完,甚至出現一秒內收到近 1800 筆回應的記錄(4:06 左右),但此階段該被視為失控狀況,不能當成有效的效能數字。因此可知,突破系統效能上限後的表現難以事先推算,變數太多,恐怕還是得實際測過才準。

以往對伺服器過載噴 503 的行為只有模糊概念,這次親手完實驗,觀察到實際行為長了見識,滿足。


About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK