NLog 的檔案管理策略

Posted on In , Views:

NLog 是 .NET 開發領域常用的 log 管理工具，操作簡單、功能齊全，內建歸檔與壓縮機制。然而前陣子我們團隊因為 NLog 的檔案管理策略設定不當，線上服務在每天歸檔的期間有機會出現幾秒到十幾秒的明顯異常。本篇以這個事故為契機，先完整復盤問題本身，再整理使用 NLog 管理 log 時的設定原則與風險，避免日後再度踩坑。

問題

背景

  1. 不會每天發生，偶爾幾天會有問題，其它幾天完全沒有症狀。
  2. 出問題時間約略落在 12:00 PM UTC+8 後的幾秒鐘內，一定不會發生在這個時間點之前。
  3. 出問題的時間帶長度每次都不一樣（例如：可能只持續 10 秒，也可能長達 15 秒），開始時間也有些微差異（從 12:00:01 到 12:00:03 之間開始出問題）。
  4. 出問題的時間帶內，有些微的 CPU High 和 Memory High 的症狀，但不到癱瘓整個服務的嚴重程度。
  5. API 呼叫端遭遇到大量的無法收到預期結果的問題，大量使用者操作無法成功。
  6. 失敗的 API 不具共同性，也就是說有多個 API 會出問題，但從單一 API 來看又是有些成功有些失敗。
  7. 失敗的 API 在出問題時間內陸續有執行成功的紀錄，且分散在整個時間帶。
  8. 失敗期間 ELK Log 關於 Application Log 的紀錄顯示有執行的請求量大幅降低。

診斷脈絡

  • 不是固定排程拖累系統，那個時間沒有高耗能排程。
  • 發生問題的時間帶過於精準，不是偶發性的高流量（否則時間不會這麼精準），不是特定 API 效能問題（否則時間不會這麼精準，也不會有上面 1、6、7 的特性，且 4 的問題應該會更嚴重）。

根據以上，根因可能是系統在某個時間點才會開始做的行為，這個行為會大量佔用系統的某種資源，且具有「會釋放但來不及釋放」的特性。根據第 2 點顯示，這個行為一定會，且非常精準的在 12:00 PM UTC+8 後極短時間內發生。

經過和 AI 密集的討論可能性，最後將問題聚焦到 NLog 的壓縮歸檔過程。當時我們並不清楚 NLog 在歸檔（含壓縮）期間，會把對應的 log 檔案鎖住，使得所有走到寫 log 這一步的呼叫都會被擋住、等待整個歸檔流程結束。在 ASP.NET Core 環境下，發出寫 log 呼叫的執行緒通常就是處理 HTTP 請求的執行緒池 (ThreadPool) 中的工作執行緒，這些執行緒被卡住後無法被釋放去處理其他工作，當被佔住的數量超過執行緒池當下可用的工作執行緒數，就會進入 執行緒池飢餓 (thread pool starvation)：執行緒池雖會動態擴張，但超過最小執行緒數後成長速率有節流（大致是秒級才能新增一條執行緒），新進的請求因此來不及被接走。當 log 體積夠大時，壓縮本身可以耗時數秒，這幾秒對執行緒池而言已經足以累積出明顯的飢餓現象。後續也透過在本機實驗證實了上面的推論。

復盤並解釋症狀

根據上面背景來一條一條復盤並解釋。

  1. 對應第 1 點：每天的 log 量不同，流量不夠高的幾天壓縮在極短時間內完成，或壓縮期間累積的請求不夠多，被卡住的執行緒數不足以觸發執行緒池飢餓，自然不會引發後續問題。
  2. 對應第 2、8 點：時間特性符合 NLog 的歸檔切點設定。歸檔壓縮一開始，所有寫 log 的呼叫就會被擋著等歸檔結束；初期執行緒池還有工作執行緒餘裕所以對外無感，一旦可用的工作執行緒耗盡、又卡在執行緒池擴張的節流上，新請求就無法被及時接收與排程進來執行 application 程式碼。再加上即使是已經在處理中的請求，只要呼叫到 logger 也會被同一把鎖擋住寫不進去，兩者疊加就是第 8 點 application log 量驟降的現象。
  3. 對應第 3 點：時間帶長度與開始時間的些微差異，分別來自「壓縮本身的耗時隨 log 大小變動」與「鎖釋放後消化累積請求 + 執行緒池補齊工作執行緒的速度視當下飢餓深度而定」這兩個變因。壓縮本身視 log 大小通常落在 3 秒上下，整個時間帶視情況可以拖到 10 ~ 20 秒。
  4. 對應第 6、7 點：壓縮前期執行緒池還沒進入飢餓時，本來就會陸續收到各種不特定 API 請求，這些請求都被攔在寫 log 的鎖上；壓縮結束、鎖釋放後，被卡住的執行緒才陸續放行，有些請求來得及把事情做完、有些已經超時。因此失敗在 API 之間不具共通性，時間帶內也會散布著成功的紀錄。
  5. 對應第 4、5 點：大量寫 log 呼叫被卡住，這些執行緒連同它們持有的 request context 都無法釋放，造成 Memory 緩步上升；CPU 偏高則來自壓縮本身（CPU bound 的工作）以及鎖釋放後同時消化大量積壓請求的瞬間負載。但因為執行緒池飢餓很快發生、新請求根本進不來，不會走到「無限接收請求並無限累積資源」的失控情境，整體因此維持在「明顯異常但不到完全癱瘓」的程度。

後續調整與設定原則

這次事故讓我們重新檢視 NLog 的檔案管理設定，整理出兩個方向：「單檔大小要有上限」與「不要讓 NLog 自己做壓縮」。

設定單檔大小上限

有兩個理由要設定單一 log 檔案的大小上限：

  1. 檢視工具的可用性：上線後 log 會持續被寫入，若再加上 Debug 等較詳細的等級，檔案很快會膨脹到幾百 MB 以上，常用的編輯或檢視工具（Notepad++、VS Code、各類 log 分析工具）可能會變慢甚至開不動。
  2. 限縮單次歸檔的耗時：單檔越小，每次歸檔（含壓縮）需要處理的資料量越小，鎖檔時間就越短，事故的影響範圍也越輕。

具體做法是用 archiveAboveSize 設定上限，超過就自動拆檔：

1
2
3
4
5
6
<target xsi:type="File" name="logfile"
        fileName="logs/logfile.log"
        archiveFileName="logs/archives/log.{#}.log"
        archiveAboveSize="52428800"  <!-- 50MB -->
        archiveNumbering="Rolling"
        maxArchiveFiles="30" />

上述設定代表單一 log 檔案超過 50MB 時自動歸檔並開新檔，最多保留最近的 30 個歸檔檔案。

處理歸檔壓縮的鎖檔風險

事故的直接成因是「NLog 在歸檔（含壓縮）期間會鎖住 log 檔案」。如「問題」段所述，這在 ASP.NET Core 高流量環境下很容易引發執行緒池飢餓。實務上有幾種應對方案：

  • 避免壓縮，直接歸檔（推薦）：
    只要磁碟空間夠，就關閉 NLog 的壓縮功能、改用純歸檔。用磁碟空間換服務穩定性，是最徹底的解法。
  • 縮短單檔大小，降低鎖檔時間（治標）：
    搭配前一節的單檔上限設定，單次壓縮越快、鎖檔時間越短。但根本上鎖檔還是會發生，只是把風險窗口縮小。
  • 改用外部排程工具壓縮（不建議）：
    用 Windows Task Scheduler 或 Linux cron 定期把歸檔後的 log 拿去壓縮，繞過 NLog 的鎖檔。問題是這多了一條外部依賴，容易發生「設定沒同步」、「同事不知道有這個機制」、「任務失敗沒人察覺」等狀況，維護與交接成本高，個人不推薦。

參考

ChatGPT