我們用了不到200行代碼實現的文件日誌系統，極佳的IO性能和高並發支持，附壓力測試數據

很多項目都配置了日誌記錄的功能，但是，卻只有很少的項目組會經常去看日誌。原因就是日誌文件生成規則設置不合理，將嚴重的錯誤日誌跟普通的錯誤日誌混在一起，分析起來很麻煩。

其實，我們想要的一個日誌系統核心就這2個要求：

1. 日誌文件能夠按照 /_logs/{

   group

   }/yyyy-MM/yyyy-MM-dd-{sequnce}.log 這樣的規則生成；
2. 調用寫日誌的方法能夠帶

   group

   這個

   字元串

   參數，差不多是這樣：LogHelper.TryLog(string group, string message);

這樣的日誌系統最大的好處就是可以幫助我們一目了然的發現嚴重錯誤。結合管理員後台直接訪問的文件系統（或Windows資源管理器），可以隨時查看/刪除系統記錄的日誌。如下圖：

上面這張圖片就可以很方便的告訴我們，系統是否發生了急需解決的bug。這也是我們覺得一個日誌系統最大的好處。

但是，現成的日誌框架中，我們花了很多時間也沒有找到一個正好解決上面兩個需求的框架，於是，喜歡重複發明輪子的我就花了1個小時寫了一個簡單、高效、調用方便的日誌系統。

1. 高並發：必須支持高並發的http請求；

2. 文件鎖：佔用文件系統（文件鎖）的時間越少越好，因為管理員可能需要隨時把日誌文件導出來，以及刪除日誌文件（不要在刪除時提示文件被佔用）；

3. 無異常：記錄日誌的方法絕不能拋任何異常（其實就是最外層包了一個try-catch）；

4. 高性能：加了記錄日誌的方法之後對系統性能幾乎沒有影響；

5. 靈活：支持任意字元串作為錯誤等級（特殊字元除外），用於生成目錄名稱。

好了，是時候上代碼了。

1 using System;
2 using System.Collections.Generic;
3 using System.IO;
4 using System.Text;
5 using System.Timers;
6
7 namespace MvcSolution
8 {
9 public class FileLogger : DisposableBase, ILogger
10 {
11 private const int IntervalSeconds = 1;
12 private const long MaxPerFileBytes = 1024000;
13 private readonly Dictionary _dict;
14 private readonly Timer _timer;
15 private bool _busy = false;
16
17 public FileLogger
18 {
19 this._dict = new Dictionary;
20 this._timer = new Timer(IntervalSeconds * 1000);
21 this._timer.Elapsed += TimerElapsed;
22 }
23
24 public void Start
25 {
26 _timer.Start;
27 }
28
29 public void Stop
30 {
31 _timer.Stop;
32 }
33
34 private void TimerElapsed(object sender, ElapsedEventArgs e)
35 {
36 if (_busy)
37 {
38 return;
39 }
40 try
41 {
42 _busy = true;
43 this.DoWork;
44 }
45 catch (Exception)
46 {
47
48 }
49 finally
50 {
51 _busy = false;
52 }
53 }
54
55 private void DoWork
56 {
57 var items = new List;
58 lock (_dict)
59 {
60 foreach (var key in _dict.Keys)
61 {
62 var group = this._dict[key];
63 if (group.Sb.Length == 0)
64 {
65 continue;
66 }
67 items.Add(new WritingItem(group));
68 group.Sb.Clear;
69 }
70 }
71 if (items.Count == 0)
72 {
73 return;
74 }
75 this.WriteToFile(items);
76 lock (_dict)
77 {
78 foreach (var item in items)
79 {
80 var group = this._dict[item.Group];
81 group.LastDate = item.LastDate;
82 group.LastFilePath = item.LastFilePath;
83 }
84 }
85 }
86
87 public void Entry(string group, string message)
88 {
89 lock (this._dict)
90 {
91 if (!this._dict.ContainsKey(group))
92 {
93 this._dict[group] = new LoggingGroup(group);
94 }
95 this._dict[group].Sb.Append("
" + message + "

");
96 }
97 }
98
99 private void WriteToFile(List items)
100 {
101 lock (this)
102 {
103 foreach (var item in items)
104 {
105 try
106 {
107 var date = DateTime.Today.ToString("yyyy-MM-dd");
108 FileInfo file;
109 if (item.LastDate == date)
110 {
111 file = new FileInfo(item.LastFilePath);
112 var parent = file.Directory;
113 if (parent.Exists == false)
114 {
115 Directory.CreateDirectory(parent.FullName);
116 }
117 if (file.Exists && file.Length > MaxPerFileBytes)
118 {
119 var yearMonth = DateTime.Today.ToString("yyyy-MM");
120 var date2 = DateTime.Now.ToString("yyyy-MM-dd-HHmmss");
121 var relativePath = $"\_logs\{item.Group}\{yearMonth}\{date2}.log";
122 file = new FileInfo(AppContext.RootFolder + relativePath);
123 }
124 }
125 else
126 {
127 var yearMonth = DateTime.Today.ToString("yyyy-MM");
128 var relativePath = $"\_logs\{item.Group}\{yearMonth}\{date}.log";
129 file = new FileInfo(AppContext.RootFolder + relativePath);
130 var parent = file.Directory;
131 if (parent.Exists == false)
132 {
133 Directory.CreateDirectory(parent.FullName);
134 }
135 }
136 File.AppendAllText(file.FullName, item.Text);
137
138 item.LastDate = date;
139 item.LastFilePath = file.FullName;
140 }
141 catch (Exception)
142 {
143
144 }
145 }
146 }
147 }
148
149 private class WritingItem
150 {
151 public string Group { get; }
152 public string Text { get; }
153 public string LastDate { get; set; }
154 public string LastFilePath { get; set; }
155
156 public WritingItem(LoggingGroup group)
157 {
158 this.Group = group.Key;
159 this.Text = group.Sb.ToString;
160 this.LastDate = group.LastDate;
161 this.LastFilePath = group.LastFilePath;
162 }
163 }
164
165
166 private class LoggingGroup
167 {
168 public string Key { get; }
169 public StringBuilder Sb { get; }
170 public string LastDate { get; set; }
171 public string LastFilePath { get; set; }
172
173 public LoggingGroup(string key)
174 {
175 this.Key = key;
176 this.Sb = new StringBuilder;
177 this.LastDate = "";
178 this.LastFilePath = "";
179 }
180 }
181
182
183 protected override void DisposeInternal
184 {
185 _timer.Dispose;
186 }
187
188 ~FileLogger
189 {
190 base.MarkDisposed;
191 }
192 }
193
194 }

View Code

上面這個FileLogger類就是我們寫的文件日誌系統的核心類了。

首先要明白這個類有一個定時器Timer，這個Timer有什麼用呢？Timer的用處就是定時將內存中記錄的日誌寫入到磁碟，推薦設置為1秒寫入一次。

正是因為有了這個Timer，才實現了高並發的處理。其原理大概是這樣：

由於WEB伺服器每秒鐘可能會處理大量的http請求，如果某個請求拋了異常需要記錄日誌，這時候如果每個請求都直接往磁碟中寫數據，那麼磁碟開銷是極其高的，並且文件鎖會導致大量排隊，這就極大的影響了WEB伺服器的性能。所以，更好的做法是：每個http請求內拋的異常先寫到內存（就是FileLogger類的StringBuilder啦），然後再定時將內存中的日誌寫入到磁碟，這樣處於性能瓶頸的磁碟操作就變成單線程操作了。

真的很簡單啦，我們只是建了一個非常簡單的helper類，如下：

1 using System;
2 using System.Text;
3 using System.Web;
4
5 namespace MvcSolution
6 {
7 public class LogHelper
8 {
9 private static ILogger _logger;
10 public static ILogger Logger
11 {
12 get
13 {
14 if (_logger == null)
15 {
16 _logger = Ioc.Get;
17 }
18 return _logger;
19 }
20 }
21
22 public static void TryLog(string group, Exception exception)
23 {
24 try
25 {
26 var sb = new StringBuilder($"【{DateTime.Now.ToFullTimeString()}】{exception.GetAllMessages}
[stacktrace]:
{exception.StackTrace}
");
27 AppendHttpRequest(sb);
28 Logger.Entry(group, sb.ToString);
29 }
30 catch (Exception)
31 {
32
33 }
34 }
35
36 public static void TryLog(string group, string message)
37 {
38 try
39 {
40 var sb = new StringBuilder($"【{DateTime.Now.ToFullTimeString()}】{message}
");
41 AppendHttpRequest(sb);
42 Logger.Entry(group, sb.ToString);
43 }
44 catch (Exception)
45 {
46
47 }
48 }
49
50 private static void AppendHttpRequest(StringBuilder sb)
51 {
52 if (HttpContext.Current == null)
53 {
54 return;
55 }
56 var request = HttpContext.Current.Request;
57 sb.Append($"[{request.UserHostAddress}]-{request.HttpMethod}-{request.Url.PathAndQuery}
");
58 foreach (var header in request.Headers.AllKeys)
59 {
60 sb.Append($"{header}: {request.Headers.Get(header)}
");
61 }
62 }
63 }
64 }

然後在WEB應用程序啟動的時候，注入ILogger的實現類為FileLogger並啟動FileLogger的Timer定時器：

調用的地方如下方代碼所示：

public ActionResult Log
{
LogHelper.TryLog("home-log", "阿克大廈卡薩丁卡薩丁，暗殺神大，啊實打實大拉聖誕快樂啊，阿薩斯柯達速度快八十多，啊實打實大咖快睡吧");
return new ContentResult{Content = "ok"};
}

public ActionResult Loge
{
try
{
var i = int.Parse("abc");
}
catch (Exception ex)
{
LogHelper.TryLog("home-log-ex", ex);
}
return new ContentResult { Content = "ok" };
}

性能測試

測試環境用的VS2017自帶的IIS Express。之前寫過一篇博文講IIS多線程工作機制的，有興趣的朋友可以轉過去看看，對於理解高並發壓力測試有幫助哦：

測試工具：ab（全稱ApacheBench）

測試代碼：MvcSolution.Web.Public.Controllers.HomeController下面的Log和Loge兩個方法

總請求數：10萬

並發：1000

最關心的指標：Requests per second，每秒處理請求數，也叫吞吐率。

測試1：使用LogHelpper.TryLog(string group, string message)方法記錄日誌，下面是測試結果截圖：

可以看到全部執行成功，每秒處理請求數：420次；

測試2：使用LogHelpper.TryLog(string group, Exception exception)方法記錄日誌，下面是測試結果截圖：

每秒處理請求數：397次；

測試3：我們想看看把記錄日誌的代碼注釋掉後，該方法本來的吞吐率，請看下方測試結果截圖：

每秒處理請求數：436.

結論：即使使用TryLog(string group, Exception exception)重載，對系統的影響為：（436-397）/436 = 8.9%。先不要被這個8.9%嚇到了，這數字是基於每個請求都記錄日誌的情況下產生的，而在實際項目運行過程中，如果算1000次請求記錄一次錯誤日誌的話，那就變成0.0089%了，不到萬一之影響啊。

如果按照TryLog(string group, string message)重載，對系統的影響為：（436-421）/436 = 3.4%，換算成每千次請求記錄一次日誌，則只有0.0034%的影響。而這個重載還是我們系統中用的最多的一個記錄日誌的方法。

所以，現在可以放心的使用這個日誌系統了。

所以，自己寫一個高性能日誌系統也沒有那麼難嘛。

本文中所有的代碼已提交到我們的ASP.NET MVC開源框架 MVCSolution項目中了，GitHub地址：

MVCSolution 是我們團隊基於ASP.NET MVC搭建的一整套WEB應用程序框架，包括大量的最佳實踐，代碼包含：單元測試、EF CodeFirst 資料庫定義、資料庫訪問、資料庫事務最佳實踐、日誌系統、加解密、JSON/XML序列化和反序列化、session管理、內存隊列管理、多層級異常處理、標準ajax框架、以及基於grunt的JavaScript前端框架。

由於有不少朋友在學習MvcSolution的過程中遇到一些問題或者想問問為什麼這麼設計，於是我們建了一個QQ群方便大家交流：539301714，歡迎加群哦~

後面我們還會將admin後台通過web方式查看和管理日誌文件系統的源碼公開出來，到時也會提交到MvcSolution，感興趣的朋友歡迎關注哦。

喜歡這篇文章嗎？立刻分享出去讓更多人知道吧！