深入理解系统中log机制（上）

作者：feihu
来源：http://feihu.me/blog/2014/insight-into-log/

最近在部门内部做了一个关于log机制的知识分享，深入的探讨了log机制中各种概念的来源、常用log库的用法、内部处理流程，以及如何在一个涉及多台主机的复杂系统中部署log等问题。本文是对这次分享的总结，将对这些问题一一展开介绍。

开场

log如今已经成为了我们日常开发时所必不可少的工具，它同debug一起构成了开发者手中分析问题最有力的两个武器。

通常相比于debug来说，log在很大程度上可以更方便、更迅速的让开发者分析程序的问题，尤其是对于非常庞大的系统、或者已经发布的程序，又或者一些非必现的问题，当我们无法方便的debug问题程序时，log文件可以提供非常多有用的信息，如果开发者log写得比较合适，大多数情况下根据log就可以分析出问题所在。因此，log分析法深受开发者的喜爱。

实际上我们在平时的代码中不知不觉中已经或多或少使用了简单的log，那一条条控制台的cout与printf就是最好的证明。

尽管现如今对于每一种开发语言都有非常多的库来帮我们处理log，本文暂时先不讲这些log库的用法，让我们先从无到有，从一个个简单的使用场景一步一步分析log库中各种概念如何发展而来。当然，我没有去真正追究它的历史，只是从个人需求角度分析得来。

最简单的log

代码中经常会需要打印一些提示信息用于显示程序工作流程，或者反馈错误信息，这就是所谓的log，就像船员的航海日志一样，我想log也是由此得名吧。为了输出这些信息，在C/C++中最简单的方法是用printf或者std::cout：

增加有用的信息

我们本可在每处需要打印log信息时都采用这种方式，但不妨先停下来试想一下，如果在一个log文件中你看到满屏幕的这种信息，但是却无法知道是在哪个文件，在什么时候，什么位置输出这条信息，那这种log的价值便大大折扣。于是，你会需要在每条log中增加一些额外有用的信息：

这样，每条log就有了时间，文件和行号这些额外有用的信息，非常有利于分析问题。

简化调用：封装

但是，这样会不会太麻烦？每次在写代码时，打印一条简单的log你需要加这么多无关的内容，万一忘了怎么办，这简直无法接受。你想要把所有的注意力都放在log本身上，不想关注其它的细技末节，怎么办？注意看，上面的函数调用中，后三个参数都是固定的，于是你可以对它进行这样简单的封装：

注：这里用宏而不采用函数，因为如果是函数的话，__LINE__的值会一直是函数中的行号，是一个固定值，而不是调用处的行号。另外，这个版本的宏只支持一个参数，后面调用它的其它函数中传了可能不止一个参数，是为了演示方便。各位有兴趣的话可以自行写出合适的printf0版本。

还是一样简单的调用，不需要你再去输入一些无关的内容，因为这个封装的函数已经替你做好了。

设定等级：TraceLevel

log信息并不是千篇一律只起一种作用，有的是纪录程序的流程，有的是错误信息，还有一些是警告信息。为了让log更有可读性，你可能想要把不同的信息区分开来，比如这样：

那么，你就可以通过在log文件中搜索Normal、Warning或者Error这些关键字就能够找到特定的log。这对于排错帮助非常大，比如你只需要搜索Error关键字就能够得出程序的出错信息。

但是，这些Normal、Warning以及Error关键字需要你每次都加在要输出的字符串中，同前面一样，你还是只想关注log本身，不愿意log和其它的信息混在一起。于是可以这样做：

现在你只需要指定一种log类型，就可以全心全意的处理log信息本身了。我们把上面的Normal, Warning和Error叫做TraceLevel，故名思义，它表示log的等级。

可以进一步简化：

如此一来，对于特定等级的log只需调用各自的log输出函数即可，除此之外，注意力全部放在log信息本身上。

在代码中，通常最多的log是Normal类型，即显示程序流程。有时你可能只想log文件中存储Warning和Error类型的信息，Normal对你来相当于干扰信息，而且log文件也会因此变得很大。有时你又会想让log中包含所有类型。如何协调？如果可以动态的选择哪些等级的信息输出，那岂不是log文件就变得像是根据我的需求定制一般，可以随意控制log包含哪些级别的信息么？

根据这一思路，代码可以这样改变：

这里暂时没有采用前面简化的方法。

getLevel1()从配置文件中读取当前允许的Level，代码中只有高于当前Level的log才会被输出，现在log文件便可以随着你的需要而定制了。

多一些控制:Marker

再来考虑这样一种情况，如果你的文件非常大，中间要输出的Normal log非常多，分为不同层次，比如：粗略的流程，详细一些的，十分详细的。和很多命令的-verbose参数一样。由于都是Normal类型的log，所以不能够用前面的TraceLevel，这时需要引入另外一层控制：

这里提供了四级的控制，和前面的TraceLevel一样，它也可以通过配置文件配置。假设现在配置的是TRACE_1，那么代码中想要输出的三条信息中，只有前两条能够输出。这层控制我们称之为Marker。

注意到这里定义的四级控制是可以通过位来操作的，能够任意组合。如果想要TRACE_1和TRACE_2都能够输出，那么只需要设置：

如果marker设置为SUB，则表明全部输出。通过增加这层控制后，log的订制变得更加灵活。

改变目的地

到目前为止，所有的log都写到控制台。如果你想log写到文件中怎么办？如果不是控制台应用程序，比如，Win32或者MFC程序，log又该写到哪里去？也许你想到可以使用fwrite代替前面的printf，但是如果你想同时能够将log写到控制台，又写到文件中或者其它地方怎么办？

放弃这种硬编码的方法吧，你可以想到一种更加灵活，可以像前面TraceLevel和Marker一样容易配置的方法，能够更加优雅的控制log输出的目的地，但不需要硬编码在代码中，而是可以配置的。一起来看下面这段代码：

这里定义了一个叫做Appender的基类，可以理解为处理log目的地的类，它有一个方法printf，对应着如何处理传给它的log。

接下来定义了三个子类，分别代表输出目的地为控制台、文件和Windows的EventLog。它们都覆写了基类的printf方法，按照各自的目的地处理log的流向，比如ConsoleAppender调用前面的printf2函数，而FileAppender可能调用类似的fwrite。这样一来，只要我们为一个程序配置用哪些Appender，log就可以根据这些配置交给对应的Appender子类处理，从而无需在代码中硬编码。

这处理每一种目的地的类我们称之为Appender。

独立控制模块：Category

现在我们的log机制已经足够的完善。但是，随着程序规模越来越大，一个程序所包含的模块也越来越多，有时你并不想要一个全局的配置，而是需要每一个模块可以独立的进行配置，有了前面的介绍，这个需求就变得很简单了：

对比前一节的代码，可以发现这里除了增加一个参数const char *cat以外，其它完全一样。但正是这个参数的出现，才让每一个模块可以独立的配置。这种模块间独立进行配置的方法我们称为Category。

配置文件

前面多次提到配置，为了达到可以灵活配置的目的，通常会将这些配置保存成一个文件，比如logConfig.ini：

那么在什么时机读取这个配置文件？一般有这样几种方式：

• 程序启动时载入logConfig.ini，如果配置不常改变时可以采用这种方式，最简单。
• 创建一个新线程，间隔一段时间检查logConfig.ini是否已经改变，如果改变则重新读取。这种方法比较复杂，可能会影响效率，而且间隔的时间也不好设置。
• 处理每一个log之前先检测logConfig.ini，如果有改变则重新读取。
• 最后一种方法结合了前两种方法的优点，还是在处理每个log之前检测，但不同的是再加上一个时间间隔，如果超过时间间隔才会真的去检测，而如果在间隔内，则直接忽略。这种方法更加高效且消耗资源最少。

对于后面三种方式，每次配置文件有了更新之后，log输出几乎可以实时的作出应变。至此，一个简单灵活的log原型建立了，但是这个log雏形完全是小儿科式的代码，只是起一个演示作用，实际上我们无需重新发明轮子。如本文开始所介绍，已经有非常多专业的库来处理log，在下篇文章中将讲述log库的用法