问题起因
依然是在使用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日志的交叉。
看似这个是一个规律（套用同事的一句话：一次发生时偶然，两次发生就是科学了）。然而此时我其实依然不太相信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）：
| | 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的时候，因而要尽量避免。
posted on 2015-08-13 16:28
dlevin 阅读(9758)
评论(4) 编辑 收藏 所属分类:
gemfire 、
logging