問題起因
依然是在使用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 閱讀(9921)
評論(4) 編輯 收藏 所屬分類:
GemFire 、
Logging