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日志的交叉。 以及同一个Appender在doApppend时：

	NFS	LOCAL
1 writer, 11M	443ms	238ms
1 writer, 101M	2793ms	992ms
10 writers, 11M	~4400ms	~950ms
10 writers, 101M	~30157ms	~5500ms