分享我们用了不到200行代码实现的文件日志系统，极佳的IO性能和高并发支持，附压力测试数据

Posted 2020-09-24 Leo‘s Blog

 很多项目都配置了日志记录的功能，但是，却只有很少的项目组会经常去看日志。原因就是日志文件生成规则设置不合理，将严重的错误日志跟普通的错误日志混在一起，分析起来很麻烦。

 

其实，我们想要的一个日志系统核心就这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<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，感兴趣的朋友欢迎关注哦。