十年资深BAT企业大牛,教你C++日志系统如何设计
笔者在写作本章节的时候,并不敢把此章节的标题叫做《高性能日志系统的设计》,之所以不敢加上“高性能”三个字的原因是,第一,我的对于日志系统设计知识和经验都来自于学习和工作经验,我并不是原创者,只是知识的搬运工;第二,目前有许多优秀的、被广泛使用的开源的日志系统,他们给了我很多启发,不敢在此班门弄斧。不管怎样,笔者还是想写一些自己关于对日志系统的理解和经验,让我们开始吧。
这是小编准备的C++学习资料,加小编c/c++学习群:825414254,加群即可获取哦!
为什么需要日志
实际的软件项目产出都有一个流程,即先开发、测试,再发布生产,由于人的因素,既然是软件产品就不可能百分百没有bug或者逻辑错误,对于已经发布了生产的项目,一旦某个时刻产生非预期的结果,我们就需要去定位和排查问题。但是一般正式的生产环境的服务器或者产品是不允许开发人员通过附加调试器去排查问题的,主要有如下可能原因:
在一些大的互联网公司或者部门分工明确的公司,开发部门、测试部分和产品运维部门是分工明确的,软件产品一旦发布到生产环境以后,将全部交由运维部门人员去管理和维护,而原来开发此产品的开发人员不再拥有相关的操作程序的权限。
对于已经上了生产环境的服务,其数据是公司的核心产值所在,一般不允许或者不敢被开发人员随意调试或者操作,以免对公司造成损失。
发布到生产环境的服务,一般为了让程序执行效率更高、文件体积更小,都是去掉调试符号后的版本,不方便也不利于调试。
既然我们无法通过调试器去调试,这个时候我们为了跟踪和回忆当时的程序行为进而定位问题,我们就需要日志系统。
退一步说,即使在开发或者测试环境,我们可以把程序附加到调试器上去调试,但是对于一些特定的程序行为,我们无法通过设置断点,让程序在某个时刻暂停下来进行调试。例如,对于某些网络通信功能,如果暂停时间过长(相对于操作系统的操作来说),通信的对端可能由于彼端没有在规定时间内响应而断开连接,导致程序逻辑无法进入我们想要的执行流中去;再例如,对于一些高频操作(如心跳包、定时器、界面绘制下的某些高频重复行为),可能在少量次数下无法触发我们想要的行为,而通过断点的暂停方式,我们不得不重复操作几十次、上百次甚至更多,这样排查问题效率是非常低下的。对于这类操作,我们可以通过打印日志,将当时的程序行为上下文现场记录下来,然后从日志系统中找到某次不正常的行为的上下文信息。这也是日志的另外一个作用。
本文将从技术和业务上两个方面来介绍日志系统相关的设计与开发,所谓技术上,就是如何从程序开发的角度设计一款功能强大、性能优越、使用方便的日志系统;而业务上,是指我们在使用日志系统时,应该去记录哪些行为和数据,既简洁、不啰嗦,又方便需要时准确快速地定位问题。
日志系统的技术上的实现
日志的最初的原型即将程序运行的状态打印出来,对于C/C++这门语言来说,即可以利用printf、std::cout等控制台输出函数,将日志信息输出到控制台,这类简单的情形我们不在此过多赘述。
对于,实际的商业项目,为了方便排查问题,我们一般不将日志写到控制台,而是输出到文件或者数据库系统。不管哪一种,其思路基本上一致,我们这里以写文件为例来详细介绍。
同步写日志
所谓同步写日志,指的是在输出日志的地方,将日志即时写入到文件中去。根据笔者的经验,这种设计广泛地用于相当数量的客户端软件。笔者曾从事过数年的客户端开发(包括pc、安卓版本),设计过一些功能复杂的金融客户端产品,在这些系统中采用的就是这种同步写日志的方式。之所以使用这种方式其主要原因就是设计简单,而又不会影响用户使用体验。说到这里读者可能有这样一个疑问:一般的客户端软件,一般存在界面,而界面部分所属的逻辑就是程序的主线程,如果采取这种同步写日志的方式,当写日志时,写文件是磁盘IO操作,相比较程序其他部分是CPU操作,前者要慢很多,这样势必造成CPU等待,进而导致主线程“卡”在写文件处,进而造成界面卡顿,从而导致用户使用软件的体验不好。读者的这种顾虑确实是存在的。但是,很多时候我们不用担心这种问题,主要有两个原因:
对于客户端程序,即使在主线程(UI线程)中同步写文件,其单次或者几次磁盘操作累加时间,与人(用户)的可感知时间相比,也是非常小的,也就是说用户根本感觉不到这种同步写文件造成的延迟。当然,这里也给您一个提醒就是,如果在UI线程里面写日志,尤其是在一些高频操作中(如Windows的界面绘制消息WM_PAINT处理逻辑中),一定要控制写日志的长度和次数,否则就会因频繁写文件和一次写入数据过大而对界面造成卡顿。
客户端程序除了UI线程,还有其他与界面无关的工作线程,在这些线程中直接写文件,一般不会对用户的体验产生什么影响。
说了这么多,我们给出一个具体的例子。
日志类的.h文件
日志的cpp文件(实现文件)
上述代码中根据日志级别定义了三个宏LOG_INFO、LOG_WARNING、LOG_ERROR,如果要使用该日志模块,只需要在程序启动处的地方调用CIULog::Init函数初始化日志:
当然,最佳的做法,在程序退出的地方,调用CIULog::Uninit回收日志模块相关的资源:
在做好这些准备工作以后,如果你想在程序的某个地方写一条日志,只需要这样写:
关于CIULog这个日志模块类,如果读者要想实际运行查看效果,可以从链接(https://github.com/baloonwj/flamingo/tree/master/flamingoclient)下载完整的项目代码来运行。该日志输出效果如下:
多线程同步写日志出现的问题一
从上面的日志输出来看,这种同步的日志输出方式,也存在时间顺序不正确的问题(时间戳大的日志比时间戳小的日志靠前)。这是由于多线程同时写日志到同一个文件时,产生日志的时间和实际写入磁盘的时间不是一个原子操作。下图解释了该现象出现的根源:
多线程写同一个日志文件出现先产生的日志后写入到文件中的现象
好在这种时间顺序不正确只会出现在不同线程之间,对于同一个线程的不同时间的日志记录顺序肯定是正确的。所以这种日期错乱现象,并不影响我们使用日志。
多线程同步写日志出现的问题二
多线程同时写入同一个日志文件还有一个问题,就是假设线程A写某一个时刻追加日志内容为“AAAAA”,线程B在同一时刻追加日志内容为“BBBBB”,线程C在同一时刻追加日志内容为“CCCCC”,那么最终的日志文件中的内容会不会出现“AABBCCABCAACCBB”这种格式?
在类Unix系统上(包括linux),同一个进程内针对同一个FILE*的操作是线程安全的,也就是说,在这类操作系统上得到的日志结果A、B、C各个字母组一定是连续在一起,也就是说最终得到的日志内容可能是“AAAAACCCCCBBBBB”或“AAAAABBBBBCCCCC”等这种连续的格式,绝不会出现A、B、C字母相间的现象。
而在Windows系统上,对于FILE*的操作并不是线程安全的。但是笔者做了大量实验,在Windows系统上也没有出现这种A、B、C字母相间的现象。
加上这种同步日志的实现方式,一般用于低频写日志的软件系统中(如客户端软件),所以,我们可以认为这种多线程同时写日志到一个文件中是可行的。