背景

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

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万行日志改造前后日志组件消耗时间

 日志组件优化报告-LMLPHP

                       

 日志组件优化报告-LMLPHP

结果如下:

单位ms

(50次平均值  测试多次结果偏差不大)

基准测试:

 日志组件优化报告-LMLPHP

 日志组件优化报告-LMLPHP

测试日志记录:

结论:

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

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

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

callgrind分析情况

后续优化计划

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

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

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

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

02-10 12:23