Log4J引起的程序“装死”

最近一次发生的日志

一周前发生的日志

看似这个是一个规律（套用同事的一句话：一次发生时偶然，两次发生就是科学了）。然而此时我其实依然不太相信Log4J是“凶手”，因为我一直觉得Log4J是一个简单的日志输出框架，它要是出问题也只是它自己的问题，是局部的，而这个问题的出现明显是全局的，直到我突然脑子一闪而过， 日志打印的操作是synchronized，也就是说在日志文件Roll的时候，所有其它需要打日志的线程都要等待直到Roll完成，如果这个Roll过程超过了2分钟，那么就会发生我们看到的Stripe Lock超时，也就是发生了程序“假死”的状态。重新查看Log4J打印日志的方法调用栈，它会在两个地方用synchronized，即同一个Category（Logger）类实例：

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