網站效能分析新手提示 - 正確解讀網站 Log 時間欄位

2025-06-17 10:55 PM

網路效能突發問題說來就來，遇上了往往只能透過事件檢視器或 IIS Log 還原現場，設法拼湊真相推敲出事發原因。

既然跟效能有關，了解不同時間點的請求執行時間變化就顯得格外重要，用耗時變化還原出時間軸常是破案的關鍵，而正確理解及利用 IIS Log 時間與耗時欄位是重要的第一步。

W3C 格式每筆記錄可包含以下欄位(* 表 IIS 預設啟用)：參考資料

Field	Appears As	Description
Date	*date	活動發生日期
Time	*time	活動發生時間，使用 UTC 時間
Service Name and Instance Number	s-sitename	用戶端運行的服務名稱和實例編號
Server Name	s-computername	伺服器名稱
Server IP Address	*s-ip	伺服器IP地址
Method	*cs-method	請求動詞，例如GET/POST
URI Stem	*cs-uri-stem	動詞目標，例如 index.html
URI Query	*cs-uri-query	用戶端嘗試執行的查詢
Server Port	*s-port	伺服器埠號
User Name	*cs-username	訪問伺服器的已驗證用戶名，匿名用戶以連字號表示
Client IP Address	*c-ip	發出請求的用戶端 IP 地址
Protocol Version	cs-version	用戶端使用的 HTTP 協議版本
User Agent	*cs(User-Agent)	用戶端使用的瀏覽器類型
Cookie	cs(Cookie)	發送或接收的 Cookie 內容（如果有）
Referrer	*cs(Referrer)	使用者最後訪問的網站，使用者由該網站提供的連結連過來
Host	cs-host	主機標頭名稱（如果有）
HTTP Status	*sc-status	HTTP 狀態碼
Protocol Substatus	*sc-substatus	子狀態錯誤碼
Win32 Status	*sc-win32-status	Windows 狀態碼
Bytes Sent	sc-bytes	伺服器發送的位元組數
Bytes Received	cs-bytes	伺服器接收並處理的位元組數
Time Taken	*time-taken	執行操作所花費的時間，單位為毫秒
Stream ID	streamid	Stream ID

分析效能問題時，我們最關心的欄位通常是 time(時間)、cs-uri-stem(呼叫哪一頁)、sc-status(200/500 成功或失敗)、time-taken(花了多少時間)。

而新手解讀網站 Log 常犯的一個錯誤是搞不清楚 time 的意義，誤把它當成請求發送時間進行推理，搞錯狀況下錯判斷。(我小時候就因此鬼打牆過...)

用一個簡單實驗來驗證。以下的 ASP.NET 網頁會先發出一個 ?m=lock 請求使用 C# lock 機制阻擋其他 ?m=ping 請求五秒鐘，接著用 setTimeout() 每隔一秒發一個 ?m=ping 共四次，這四次請求會被 ?m=lock 卡住，最後再一起傳回應：

<%@Page Language="C#"%>
<script runat="server">
    static object syncLock = new Object();
    void Page_Load(object sender, EventArgs e)
    {
        var mode = Request["m"];
        if (!string.IsNullOrEmpty(mode))
        {
            var start = DateTime.Now;
            switch (mode)
            {
                case "lock":
                    lock (syncLock)
                    {
                        System.Threading.Thread.Sleep(5000);
                    }
                    break;
                case "ping":
                    lock (syncLock) 
                    {
                        System.Threading.Thread.Sleep(1);
                    }
                    break;
                    
            }
            Response.Write(string.Format("{0:mm:ss.fff} ~ {1:mm:ss.fff} {2}", start, DateTime.Now, Request.Url.Query));
            Response.End();
        }
    }
</script>
<!DOCTYPE html>
<html>
    <head>
        <meta charset="utf-8">
        <style>
            html,body {
                font-family: 'Courier New', Courier, monospace;
            }
        </style>
    </head>
    <body>
        <ul id="msgs">

        </ul>
        <script>
            function addMsg(msg) {
                var ul = document.getElementById("msgs");
                var li = document.createElement("li");
                li.innerText = msg;
                ul.appendChild(li);
            }
            function ajax(url) {
                fetch(url).then(res => res.text()).then(text => addMsg(text));
            }
            ajax("?m=lock");
            for (var i = 0; i < 4; i++) {
                const delay = i * 1000 + 1000;
                const url = "?m=ping&n=" + i;
                setTimeout(() => ajax(url), delay);
            }
        </script>
    </body>
</html>

使用瀏覽器 F12 網頁分析工具觀察 fetch 請求發送結果如下，由最右方的時間軸可以看出 ?m=lock 及四個 ?m=ping 各自間隔一秒先後發出，最後一起獲得回應同時結束。

用以上結果對照 IIS Log，可清楚地看出「time 是結束時間」的事實，五個 /aspnet/iislogtime 請求的 time 都是 35'11"，表示 IIS 在同一秒執行完五個請求寫入 Log。而最後一欄的 time-taken 則是每個請求的執行時間，嚴格來說是 IIS 從收到第一個 Byte 到送完回應為止花費的時間，在 IIS 7.0+ 它還會包含網路傳輸時間，延伸客戶端回覆收到(Acknowlege)或重設網路連線為止參考)。

換言之，如果你想觀察某個時間起處理請求的時間是否愈來愈慢，用 time - time-taken 推算接收到請求的時間(我喜歡叫它 cs-time)，用 cs-time 排序再做分析較能看出趨勢。

要做到這點不難，若 Log 檔不大，用幾行 C# 程式即可實現，如以下範例：

using System.Globalization;

if (args.Length == 0)
{
    Console.WriteLine("syntax: calc-cstime <IIS log path>");
    return;
}
string logPath = args[0];
if (!File.Exists(logPath))
{
    Console.WriteLine($"File not found: {logPath}");
    return;
}
foreach (var line in process(logPath).OrderBy(o => o)) Console.WriteLine(line);
static IEnumerable<string> process(string logPath)
{
    using var reader = new StreamReader(logPath);
    string? line;
    while ((line = reader.ReadLine()) != null)
    {
        if (line.StartsWith("#Fields: date time "))
        {
            var fldNames = line.Split(' ');
            if (fldNames[fldNames.Length - 1] != "time-taken")
            {
                Console.WriteLine("Error: 'time-taken' must be the last field");
                break;
            }
            line = line.Replace("#Fields: date time ", "#Fields: date cs-time time ");
        }
        else if (!line.StartsWith("#"))
        {
            var p = line.Split(' ');
            var timeTaken = int.Parse(p[p.Length - 1]);
            var csTime = DateTime.ParseExact($"{p[0]} {p[1]}", "yyyy-MM-dd HH:mm:ss", CultureInfo.InvariantCulture).AddMilliseconds(-timeTaken);
            var newArray = new[] { p[0], csTime.ToString("HH:mm:ss.fff") }
                .Concat(p[1..])
                .ToArray();
            line = string.Join(' ', newArray);
        }
        yield return line;
    }
}

這段程式會讀入 Log 檔，插入 cs-time 欄位並依 cs-time 重新排序(程式未完整防呆及對考慮處理超大 Log 檔的效能優化)，轉換後的 Log 更容易依據請求先後順序推敲因果關係並觀察執行時間的變化。