日志组件优化报告

Posted 2021-02-08 kingstarer

背景

目前项目组日志组件存在以下问题：

1 日志文件每写一次日志就打开关闭一次，存在性能浪费

2 日志里面获取时间需要调用localtime、stat，在频繁调用时该函数消耗cpu比较多

3 日志组件获取环境变量时未判断是否成功，如果环境变量没设置会引起程序core

4 日志组件在写日志时，先初始化局部变量再判断日志级别，可以优化

5 日志组件里面有不少处调用了sprintf、ReplaceEnvVar和strlen，其实可以避免

6 日志组件调用了大量不可重入函数，在信号处理函数中写日志可能引起core

改造方案

1 增加文件句柄缓存与输出缓冲：

         增加一个环境变量HIGH_PERFORMANCE_LOG，默认值为0，不启用。

当HIGH_PERFORMANCE_LOG为1时，每次打开日志后将日志文件名记录到g_logInfo. sFullLogName，写完日志后暂时不执行fclose。

下次写日志时判断待写日志文件名是否与g_logInfo. sFullLogName一致，如果一致则不用重新打开文件。否则先将日志文件句柄关闭再进行打开日志文件的流程。

增加一个环境变量HIGH_PERFORMANCE_LOG_CACHE，默认值为0，不启用。在HIGH_PERFORMANCE_LOG_CACHE和HIGH_PERFORMANCE_LOG都为1时，写完日志后不立即执行刷新到磁盘（不调用fflush）

 

2 减少非必要系统函数调用：

增加函数localtime项目组代替原来的localtime，每次调用localtime项目组时先判断是否与上次调用间隔超过1分钟，如果没超过则使用上次调用localtime返回的结果，如果超过则重新调用localtime并且将结果缓存起来待下次使用。这样从原来一分钟调用多次localtime变成一分钟调用一次。

修改函数CommonGetCurrentDate，首次调用时记录当天起始秒数和第二天起始秒数，并且将返回的日志缓存起来。之后每次调用判断时间是否当天范围内，如果是则直接使用缓存返回，否则重复上面流程。样从原来天调用多次localtime变成一天调用一次。

 

增加环境变量LOG_SYSCALL_INTERVAL_TIMES，默认值为100，每写LOG_SYSCALL_INTERVAL_TIMES次日志时才执行一次stat（如果缓存打开情况，需要先调用fflush将日志缓冲刷出），不需要每写一次日志就检查一次。注意，由于每100行才检查一次日志大小，所以会影响原来50m切换一次日志文件的逻辑，不一定精确的在50m时切换，会略大一些。

 

3 获取环境变量失败增加默认值：

改造原来获取环境变量的代码，增加环境变量获取失败时使用默认值的逻辑，避免异常情况下导致程序core

 

4 将判断日志级别的逻辑往前提：

进入写日志逻辑后，先判断当前日志级别是否需要输出日志，如果不需要则直接返回。减少非必要的变量初始化操作。

5 使用耗时较小的函数代替耗时长的函数：

日志组件每次写日志时需要使用ReplaceEnvVar函数替换日志文件路径里面的变量， 现改为在初始化时就调用ReplaceEnvVar将文件路径变量替换完。后面写日志时使用ifNeedReplaceEnvVar判断是否需要替换变量，如果不需要则不调用ReplaceEnvVar

把简单的sprintf调用改为同功能其它函数代替，如将fprintf(fp, " ")改为fputc (‘ ‘, fp)

判断字符串是否为空，不使用strlen(str) == 0的写法，改为str[0] == ‘‘

非功能测试对比

测试写20万行日志改造前后日志组件消耗时间

 

                       

 

 

 

 

 

结果如下：

单位ms

	不设置环境变量	HIGH_PERFORMANCE_LOG=1	HIGH_PERFORMANCE_LOG=1 HIGH_PERFORMANCE_LOG_CACHE=1	HIGH_PERFORMANCE_LOG=1 HIGH_PERFORMANCE_LOG_CACHE=1 LOG_SYSCALL_INTERVAL_TIMES=1000
新WrtieLog	4836.7	1001.88	453.12	454.28
新HtLog	5603.4	1355.96	1253.96	1277.58
新DebugLog	7017.66	2600.98	2323.88	2333.98
旧WrtieLog	7388.92	7442.24	7196.72	7380.76
旧HtLog	7654.6	7712.28	7498.46	7655.82
旧DebugLog	9404.58	9431.44	8805.68	9049.94
效率比	0.65	0.13	0.06	0.06

（50次平均值  测试多次结果偏差不大）

 

基准测试：

 

 

 

 

测试日志记录：

 

 

结论：

 

改造后日志组件性能有所提高，效率提高约44%~70%

 

需要注意HIGH_PERFORMANCE_LOG环境变量启用的情况，如果程序写日志过程中日志文件被删除或者移走，程序不能即时发现，仍然会往原来的日志文件写日志。

需要等到写满LOG_SYSCALL_INTERVAL_TIMES行日志后才会触发日志文件重新打开关闭功能。

 

callgrind分析情况

 

 

后续优化计划

如果以后日志组件再次成为性能瓶颈，可以考虑以下优化：

1 使用linux文件映射进行日志文件读写，代替现有的标准库函数。这样可以减少数据拷贝。

2 写日志时使用流压缩，边写日志边压缩，减少磁盘消耗。

3 实在不行考虑异步落盘，先将日志数据写到共享内存，由专用的日志进程写到日志文件。