背景
目前项目组日志组件存在以下问题:
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, "\n")改为fputc ('\n', fp)
判断字符串是否为空,不使用strlen(str) == 0的写法,改为str[0] == '\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 实在不行考虑异步落盘,先将日志数据写到共享内存,由专用的日志进程写到日志文件。
~~积土成山,风雨兴焉;积水成渊,蛟龙生焉;~~~