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

文章出處

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

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

日志文件能夠按照 /_logs/{group}/yyyy-MM/yyyy-MM-dd-{sequnce}.log 這樣的規則生成；
調用寫日志的方法能夠帶 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<string, LoggingGroup> _dict;
 14         private readonly Timer _timer;
 15         private bool _busy = false;
 16 
 17         public FileLogger()
 18         {
 19             this._dict = new Dictionary<string, LoggingGroup>();
 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<WritingItem>();
 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("\r\n" + message + "\r\n\r\n");
 96             }
 97         }
 98 
 99         private void WriteToFile(List<WritingItem> 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啦），然后再定時將內存中的日志寫入到磁盤，這樣處于性能瓶頸的磁盤操作就變成單線程操作了。

如何使用這個FileLogger呢？

真的很簡單啦，我們只是建了一個非常簡單的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<ILogger>();
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()}\r\n[stacktrace]: \r\n{exception.StackTrace}\r\n");
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}\r\n");
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}\r\n");
58             foreach (var header in request.Headers.AllKeys)
59             {
60                 sb.Append($"{header}: {request.Headers.Get(header)}\r\n");
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多線程工作機制的，有興趣的朋友可以轉過去看看，對于理解高并發壓力測試有幫助哦：

http://www.cnblogs.com/leotsai/p/understanding-iis-multithreading-system.html

測試工具：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%的影響。而這個重載還是我們系統中用的最多的一個記錄日志的方法。

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

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

獲取源碼并加入討論QQ群：539301714

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

https://github.com/leotsai/mvcsolution

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

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

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

文章列表