<acronym id="cr5pu"></acronym>
  • <kbd id="cr5pu"><font id="cr5pu"></font></kbd>
  • <li id="cr5pu"><output id="cr5pu"></output></li>
    <del id="cr5pu"><li id="cr5pu"></li></del><center id="cr5pu"></center>
    <output id="cr5pu"><kbd id="cr5pu"></kbd></output>
  • <rp id="cr5pu"></rp>
    <var id="cr5pu"></var>
  • <nav id="cr5pu"></nav>
  • 上善若水
    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 閱讀(9850) 評論(4)  編輯  收藏 所屬分類: GemFire 、Logging

    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功能。  回復  更多評論
      

    只有注冊用戶登錄后才能發表評論。


    網站導航:
     
    久久一级片
    <acronym id="cr5pu"></acronym>
  • <kbd id="cr5pu"><font id="cr5pu"></font></kbd>
  • <li id="cr5pu"><output id="cr5pu"></output></li>
    <del id="cr5pu"><li id="cr5pu"></li></del><center id="cr5pu"></center>
    <output id="cr5pu"><kbd id="cr5pu"></kbd></output>
  • <rp id="cr5pu"></rp>
    <var id="cr5pu"></var>
  • <nav id="cr5pu"></nav>