最近,我们新上线的一个程序出现了一个很诡异的问题,检查日志时,发现从0点后的日志,出现了大约10来分钟的停顿(中间没有日志),恢复的日志中更存在时间的错序,譬如显示00:11:00的日志,后面却跟着00:00:42的日志,时间错乱非常严重。log4j记录的日志,为什么会出现后发先至(而且时间差还非常之大)?在长达10分钟没有日志的时间内,系统到底在干了些什么呢?为什么为停止服务呢?由于00:00这个敏感的时间点,这个时段正好是log4j切换日志文件的时间,由于我们的日志量很大,而且切换后自动进行了压缩,那么是否是在压缩期间,由于系统资源严重耗尽,譬如CPU、内存,导致系统停止服务呢?这种可能性感觉可能,但实际上又应该不会发生,毕竟,log4j的压缩也是在Java中完成的,怎么可能只做压缩,而其它线程却没有执行调度呢?通过重现日志切换的过程,这个问题得到了重现,也彻底的找到了原因:
1、log4j的日志记录,对FileAppender来说,是采用synchronize机制进行同步的,这确保了日志不会混错在一起。
2、log4j在进行日志切换时间点时,这个操作也是在synchronize的控制之内,也就是说,在完成压缩旧有的文件之前,其它所有的log操作都会被堵塞。很显然,这样的设计是不符合7*24小时大型应用的。
3、不巧的是,我们的这台服务器比较老旧,压缩一个2G的文件竟然需要10分钟时间,这也是这段时间的log都被阻塞的原因了。
4、当压缩完成后,已挤压的大量的log操作重新唤醒,这是,执行的先后顺序就没有保证了,可能前面的请求后被唤醒。这就是导致错序的原因。

解决方案 »

  1.   

    你用过RollingFileAppender的TimeBasedRollingPolicy 吗?
      

  2.   

    个人认为 log4j 不可能出现这样的 BUG,检查一下你们应用中涉及日志的代码吧。
      

  3.   

    显然是自己程序设计上的问题。日志切换这件事情,直接交给Log4j自行完成,有Roll的记录器的。日志压缩本来就不应该跟日志切换一起做,建议另外开批处理程序(甚至可以不用Java写),定时比如:凌晨2点左右才开始做这种需要大量消耗CPU资源和磁盘IO的事情。
      

  4.   

    首先我看了log4jdebug列表,没有发现楼主类似问题。
    所以我觉得楼主碰到的问题是log4j的bug的可能性不大。
    应该是使用的问题,可以的话把log4j的配置文件内容和相关代码贴上来吧。
    否则除非有人遇到过一样的问题,否则不能给你修改意见。