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,
            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）：

一些其他的统计：

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的时候，因而要尽量避免。