最近,我们新上线的一个程序出现了一个很诡异的问题,检查日志时,发现从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、log4j的日志记录,对FileAppender来说,是采用synchronize机制进行同步的,这确保了日志不会混错在一起。
2、log4j在进行日志切换时间点时,这个操作也是在synchronize的控制之内,也就是说,在完成压缩旧有的文件之前,其它所有的log操作都会被堵塞。很显然,这样的设计是不符合7*24小时大型应用的。
3、不巧的是,我们的这台服务器比较老旧,压缩一个2G的文件竟然需要10分钟时间,这也是这段时间的log都被阻塞的原因了。
4、当压缩完成后,已挤压的大量的log操作重新唤醒,这是,执行的先后顺序就没有保证了,可能前面的请求后被唤醒。这就是导致错序的原因。
所以我觉得楼主碰到的问题是log4j的bug的可能性不大。
应该是使用的问题,可以的话把log4j的配置文件内容和相关代码贴上来吧。
否则除非有人遇到过一样的问题,否则不能给你修改意见。