Log4J引起的程序“装死”

问题起因

依然是在使用GemFire的集群中,我们发现偶尔会出现一些GemFire的Function执行特别慢,并且超过了两分钟(为了保证数据的一致性,我们在写之前需要先拿一个Lock,因为不能每个Key都对应一个Lock,因而我们使用了Guava的Stripe Lock(关于Stripe Lock可以参考这里),而且这个Lock本身我们指定了2分钟的超时时间,因而如果写超过两分钟,我们就会收到Exception)。这个问题其实已经困扰了我们好几年了,刚前段时间,我们发现长时间的Stop-The-World GC会引起这个问题,而且这种时候很多时候会引起那个节点从集群中退出,并不是所有的这种错误都有GC的问题,我特地查了GC的日志,有些这种写超过两分钟的情况下,GC一直处于非常健康的状态,而且查了GemFire的日志和我们自己的日志,也没有发现任何异常。由于我们每个数据保留两分份拷贝,也就是说每次数据写都要写两个节点,两分钟对CPU来说可以做太多的事情,因而只有IO才能在某些时候产生这种问题,在问题发生的时候也没有任何overflow数据,而且本地操作,即使对IO来说2分钟也是一个非常长的时间了,因而我们只能怀疑这是写另一个节点引起的,对另一个节点,它是在同一个Data Center中,而且基本是在同一个Chasis内部,因而它们之间小于1M的数据量通信也不太可能花去2分钟的时间,所以剩下的我们就只能怀疑网络的问题了,比如数据丢包、网络抖动、网络流量太大一起传输变慢等,但是我们没有找到任何相关的问题。所以我们很长一段时间素手无策,只能怪GemFire闭源,我们不知道这两分钟是不是GemFire自己内部在做一些不为人知的事情,因而太忙了而每来得及处理我们的写请求。虽然我一直觉得不管在处理什么炒作,两分钟都没有响应根本无法解释的通,更何况GemFire节点之间并没有报告有任何异常,或者像以前发现的一个节点向Locator举报另一个节点没有响应的问题,Locator自己也能很正常的向那个节点发送新的成员信息(View),因而看起来向是这个节点虽然花了两分钟多来写一个数据,但是它还是有响应的,有点“假死”的赶脚。

问题发现

这个问题这么几年以来时不时的就会发生,而且因为以前花的时间太多了,而且也没有找到任何出错的地方,现在索性不去花太多时间在上面了,更何况这个它很长时间才发生一次,并且今年以来就一直没发生过,直到前几周出现一次,我有点不信邪的重新去看这个问题,依然没有找到任何可疑的地方,GC日志、应用程序日志、GemFire自己的日志、网络、CPU使用情况等所有的都是正常的,除了问题发生的那个时刻,应用程序没有任何日志,另外在问题发生之前出现过Log4J日志文件的Rolling(我们使用RollingFileAppender,并且只保留20个日志文件),但是Log4J日志文件Roll的日志出现了断结,在开始要Roll到真正完成Roll中间还有几行GemFire自身的日志,此时我并没有觉得这个是有很大问题的,因为我始终觉得Log4J除了它自己提到平均对性能有10%的影响以外,它就是一个简单的把日志写到文件的过程,不会影响的整个应用程序本身,因为它太简单了,直到今天这个问题再次出现,依然没有任何其他方面的收获,所有的地方都显示正常状态,甚至我们之前发现的网卡问题今天也没有发生,然而同样是出问题的两分钟没有出现应用程序日志,日志文件Roll的日志和上次类似,开始Roll到结束出现GemFire日志的交叉。
最近一次发生的日志
[info 2015/08/12 01:56:07.736 BST …] ClientHealthMonitor: Registering client with member id …
log4j: rolling over count=20971801
log4j: maxBackupIndex=20
[info 2015/08/12 01:56:12.265 BST …] ClientHealthMonitor: Unregistering client with member id …
……
[info 2015/08/12 01:56:23.773 BST …] ClientHealthMonitor: Registering client with member id …
log4j: Renaming file logs/….log.19 to logs/….log.20
一周前发生的日志
[info 2015/08/04 01:43:45.761 BST …] ClientHealthMonitor: Registering client with member id …
log4j: rolling over count=20971665
log4j: maxBackupIndex=20
……
[info 2015/08/04 01:45:25.506 BST …] ClientHealthMonitor: Registering client with member id …
log4j: Renaming file logs/….log.19 to logs/….log.20
看似这个是一个规律(套用同事的一句话:一次发生时偶然,两次发生就是科学了)。然而此时我其实依然不太相信Log4J是“凶手”,因为我一直觉得Log4J是一个简单的日志输出框架,它要是出问题也只是它自己的问题,是局部的,而这个问题的出现明显是全局的,直到我突然脑子一闪而过,日志打印的操作是synchronized,也就是说在日志文件Roll的时候,所有其它需要打日志的线程都要等待直到Roll完成,如果这个Roll过程超过了2分钟,那么就会发生我们看到的Stripe Lock超时,也就是发生了程序“假死”的状态。重新查看Log4J打印日志的方法调用栈,它会在两个地方用synchronized,即同一个Category(Logger)类实例:
    public void callAppenders(LoggingEvent event) {
        int writes = 0;
        for(Category c = this; c != null; c=c.parent) {
            // Protected against simultaneous call to addAppender, removeAppender,Log4J引起的程序“装死”
            synchronized(c) {
                if(c.aai != null) {
                    writes += c.aai.appendLoopOnAppenders(event);
                }
                if(!c.additive) {
                    break;
                }
            }
        }
。。。
    }
以及同一个Appender在doApppend时:
    public synchronized void doAppend(LoggingEvent event) {
      。。。
      this.append(event);
    }
而Roll的过程就是在append方法中,进一步分析,在下面两句话之间,他们分别花费了超过100s和超过11s的时间:
log4j: maxBackupIndex=20
。。。
log4j: Renaming file logs/….log.19 to logs/….log.20
而这两句之间只包含了两个File.exists(),一个File.delete(),一个File.rename()操作:
    public void rollOver() {
      。。。
      if(maxBackupIndex > 0) {
        // Delete the oldest file, to keep Windows happy.
        file = new File(fileName + '.' + maxBackupIndex);
        if (file.exists())
            renameSucceeded = file.delete();
        for (int i = maxBackupIndex - 1; i >= 1 && renameSucceeded; i--) {
            file = new File(fileName + "." + i);
            if (file.exists()) {
                target = new File(fileName + '.' + (i + 1));
                LogLog.debug("Renaming file " + file + " to " + target);
                renameSucceeded = file.renameTo(target);
            }
        }
      。。。
      }
    }

NFS简单性能测试和分析

因而我对NFS的性能作了一些简单测试:
只有一个线程时,在NFS下rename性能:
1 file:                    3ms
10 files:                48ms
20 files:                114ms
相比较,在本地磁盘rename的性能:
1 file:                    1ms
3 files:                  1ms
10 files:                3ms
对NFS和本地磁盘写的性能(模拟日志,每行都会flush):

 

NFS

LOCAL

1 writer, 11M

443ms

238ms

1 writer, 101M

2793ms

992ms

10 writers, 11M

~4400ms

~950ms

10 writers, 101M

~30157ms

~5500ms


一些其他的统计:
100同时写:
Create 20 files spend: 301ms
Renaming 20 files spends: 333ms
Delete 20 files spends: 329ms
1000同时写:
Create 20 files spend: 40145ms
Renaming 20 files spends: 39273ms
而在1000个同时写的过程中,重命名:
Rename file: LogTest1.50 take: 36434ms
Rename file: LogTest1.51 take: 39ms
Rename file: LogTest1.52 take: 34ms
也就是说在这个模拟过程中,一个文件的rename超过36s,而向我们有十几台机器同时使用相同的NFS,并且每台机器上都跑二三十个程序,如果那段时间同时有上万个的日志写,可以预计达到100s情况是可能发生的。
关于NFS性能的问题,在《构建高性能WEB站点》的书(330页)中也有涉及。简单的介绍,NFS由Sun在1984年开发,是主流异构平台实现文件共享的首选方案。它并没有自己的传输协议,而是使用RPC(Remote Procedure Call)协议(应用层),RPC协议默认底层基于UDP传输,但是自己实现在丢包时的重传机制,而且NFS服务器采用多进程模型,默认进程为4,但是一般都会调优增加服务进程数,然而“不管怎么对NFS进行性能优化,NFS注定不适合作为I/O密集型文件共享方案,但可以作为一般用途,比如提供站点内部的资源共享,它的优势在于容易搭建,而且可以减少不必要的数据冗余。”
可以使用命令:“nfsstat -c”获取对NFS服务器的操作的简单统计,具体可以参考《构建高性能WEB站点》的相关章节,里面还有更详细的对NFS服务器性能的测试。

总结

从这个事件我总结了两件事情:
1. 日志的影响可能是全局性的,因而要非常小心,一个耗时的操作可能引起程序的“假死”,因而要非常小心。
2. 虽然把日志打印在NFS上,对大量的日志文件查找会方便很多,但是这是一个很耗性能的设计,特别是当大量的程序共享这个NFS的时候,因而要尽量避免。

上一篇:实现自己的Lock对象


下一篇:java内存查看与分析