上善若水
In general the OO style is to use a lot of little objects with a lot of little methods that give us a lot of plug points for overriding and variation. To do is to be -Nietzsche, To bei is to do -Kant, Do be do be do -Sinatra
posts - 146,comments - 147,trackbacks - 0

问题起因

依然是在使用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):

 

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 阅读(9854) 评论(4)  编辑  收藏 所属分类: GemFireLogging

FeedBack:
# re: Log4J引起的程序“装死”
2015-08-14 09:00 | otaku119
個人不才,再度跑來踢館,請版主賜教
個人沒看過<<構建高性能WEB站點>>這本書,以下留言純屬廢話
NFS算起來應該是一個規範,用於Uinx like之間的的傳輸
所以AIX、LINUX彼此的性能實作也會有所差異
因為彼此都是透過TCP/IP協做方式,所以會影響到他的效能的,除了彼此的實際實作外,應該還要考慮一個問題:MTU、封包大小等等的設定,AIX對於NFS的一點解說:http://www-01.ibm.com/support/knowledgecenter/ssw_aix_53/com.ibm.aix.prftungd/doc/prftungd/nfs_perf.htm?lang=zh-tw

又,如果是LOG紀錄,為何要多個log4J存取?
是否建立一個Adapter,專門做接收log而用
就像LINUX上,syslogd,可以在本機,也可以丟往遠端
但是syslogd,似乎沒人用網路磁碟來存放資料.....  回复  更多评论
  
# re: Log4J引起的程序“装死”
2015-08-15 12:52 | DLevin
@otaku119
多谢“踢馆”以及NFS的资料,木有仔细研究过NFS,因而只是凭自己的经验和道听途说,所以不做过多评论。

关于多个Log4J,不确定我是否理解这个问题,凭我理解的方向,每个进程有N个线程,大部分的“用户线程”都需要写日志,因而这里有多个;然后我们一台机器上有M个进程(节点)在跑;再次,有Y台机器共享相同的NFS目录。

个人猜测,syslogd没人用网络磁盘来存放资料也会和性能有关?如果有类似的需求,使用另一个Job将跟新的日志推到网络磁盘上的设计会更加合理,耦合更低,而且也更加轻巧?:)  回复  更多评论
  
# re: Log4J引起的程序“装死”
2015-08-17 08:37 | otaku119
個人的想法,因為NFS也是透過TCP/IP方式傳輸
在網路傳輸流量沒有本機I/O來的快速,加上NFS連接、傳輸時,需要耗費其他不必要的頻寬(維護成本增加)。
將網路磁碟機作為LOG記錄方式,實在看不出來有什麼優點
為何不使用以下的方法:
log4j--------->log4j(syslogd)->HDD
所有外部程式,透過log4j的SOCKT方式傳輸
https://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/net/SocketAppender.html

依照以前LINUX的管理方式,syslogd可以寫在本地端,也可以直接拋往某個IP,由某個IP上的server來記錄,
或許就是因為NFS、SAMBA的先天限制,才會有各種deamon來做接收處理?

PS:能否指導,
>>使用另一個Job將跟新的日誌推到網絡磁盤上的設計會更加合理,耦合更低,而且也更加輕巧?
所謂的耦合,是在何處?
  回复  更多评论
  
# re: Log4J引起的程序“装死”
2015-08-18 20:16 | DLevin
@otaku119
关于这个:
為何不使用以下的方法:
log4j--------->log4j(syslogd)->HDD
所有外部程式,透過log4j的SOCKT方式傳輸

不是完全理解”外部程式“在这里的实际意思,如果没理解错,我们的想法可能是类似的,把Log推到远端,主要的目的是把Log信息集合在一起,方便以后查找分析。让每个程序自身去”推“Log,增加这个程序和”推”Log这个动作的耦合,还不如程序自己打印自己的Log到本地,而“推”这个动作本身交给一个专门的程序(Job)去做,这个专门的程序可以是一个简单的脚本定期的拷贝Log文件到指定的服务器,或者如果有“实时”需求,实现一个FileWatcher功能。  回复  更多评论
  

只有注册用户登录后才能发表评论。


网站导航: