排查Java線上服務故障的方法和實例分析


 

前言

  作為在線系統負責人或者是一個技術專家,你可能剛剛接手一個項目就需要處理緊急故障,或者被要求幫忙處理一些緊急的故障,這個時候的情景是:

  (1)你可能對這個業務僅僅是聽說過,而不怎么真正了解;

  (2)你可能沒有這個故障的詳細信息,比如可能僅僅是有使用方反饋服務中斷了10分鍾;

  (3)你對代碼細節還沒有仔細研究過。

  這個時候該怎么解決問題呢?根據以前的經驗,工程師們常常傾向於直接登上服務器檢查代碼,試圖立刻修改問題。或者是把某些可能是問題的配置做修改,但並不是100%確認這就是問題的根本原因。但結果往往是在解決問題的同時引入了新的問題,或者是沒有找到問題的根本原因,導致用戶的再次投訴。

 

正文

  處理和排除故障分為4個必須的步驟:

  (1) 緊急處理

  (2) 添加監控

  (3) 使用JDK性能監控工具

  (4) 分析源代碼。從治標不治本,到治標又治本。

 

緊急處理

  緊急處理,顧名思義,是檢查和評度當前故障的影響范圍,並盡快使服務先恢復起來。其中檢查和評估當前故障的影響范圍是非常重要的。

  以微博系統舉例,一般用戶的投訴率為千分之1,如果有超過10起用戶投訴,就可能是大面積故障。如果只是負責線上跟蹤的QA人員反饋的問題,而沒有用戶投訴,則可以有較多的時間去處理。

  對於緊急的大面積故障,首先想到的不應該是檢查問題。而是需要立刻追查最近線上系統是否有更改,我們的經驗是95%的故障都是在新代碼上線后的12小時內發生的。此時應該立刻回滾新更改。另外5%的故障大部分是由於業務擴展導致的。互聯網業有一個規律,線上系統每半年需要重構一次,否則無法對應業務量的增長。對於這種業務量增長造成的故障,通常可以通過重啟服務來緊急處理。

  因此,緊急處理的首選是立刻回滾新更改

 

添加監控

  緊急處理之后,服務已經恢復了,但是問題並沒有找到。如果是新代碼上線造成的故障,回滾之后,工程師會有各種手段,在測試環境追查問題。而針對系統容量不足造成的故障,需要特別添加監控作為追查問題的重要手段。因為互聯網業務請求高峰和低谷差別非常明顯,微博業務中的請求高峰往往出現在晚上10點左右,而且不是穩定的出現。要求工程師們每天悲催的坐在電腦前守到晚上10點,卻不見得能發現問題,是非常低效的。監控一般用一個簡單的腳本就可以搞定,比如http服務監控,Shell腳本代碼如下:

  MAX_LATENCY_TIME=5    

  curl -m $MAX_LATENCY_TIME "http://1.2.3.4:8011/...."    

  if [ $? -ne 0 ] ; then  

          sIp=`hostname`  

          errmsg="gexin install latency > "$MAX_LATENCY_TIME"s"  

          // 具體告警的處理  

          echo $errmsg  

          echo send success  

  fi  

 

使用JDK性能監控工具

  剛剛添加的監控開始報警了。登上服務器,該做些什么呢?一般需要做如下動作,

  (1)首先要查看日志,看看有沒有Exception。另外日志中常常有對接口調用,緩存使用的監控告警信息。

  (2)看看目前gc的狀況如何,使用JDK自帶的工具就可以。jstat -gc -h 10 vmid 5000,每5秒打出一次。我遇到過兩次線上故障,都是簡單的通過jstat就找到了問題。一次是Permanent區分配過小,JVM內存溢出。另一次是發生了過多的Full GC,使得系統停止響應。內存造成的問題通過簡單的重啟服務就可以使得服務恢復,但重啟之后往往很快又出現問題。這個期間你要監控gc,看看期間發生了什么事情。如果是old區增長的過快,就可能是內存泄露。這個時候,你需要看看到底是什么對象占用了你的內存。

  (3)jmap -histo vmid > jmap.log,該命令會打出所有對象,包括占用的byte數和實例個數。分享一個線上jmap實例,

  Jmap.log代碼  

  num     #instances         #bytes  class name  

  ---------------------------------------------  

  1:      10540623      668712400  [B  

    2:      10532610      252782640  com.google.protobuf.ByteString  

      3:       4305941      234036872  [Ljava.lang.Object;  

      4:       1066822      170691520  cn.abc.data.protobuf.UserWrap$User  

      5:       3950998      158039920  java.util.TreeMap$Entry  

      6:       3950159      126405088  com.google.protobuf.UnknownFieldSet$Field  

      7:        780773      118677496  cn.abc.data.protobuf.StatusWrap$Status  

      8:       4305047      103321128  java.util.ArrayList  

      9:       4301379      103233096  java.util.Collections$UnmodifiableRandomAccessList  

    10:       3207948      102654336  java.util.HashMap$Entry  

    11:       2571737       82300280  [C  

    12:       2569460       82222720  java.lang.String  

    13:       3952892       63246272  java.lang.Integer  

    14:       1314438       63093024  java.util.TreeMap  

    15:       2533229       60797496  java.lang.Long  

    16:       1065093       51124464  cn.abc.data.protobuf.PostSourceWrap$PostSource  

    17:       1314430       42061760  java.util.Collections$UnmodifiableMap  

    18:        284198       40924512  cn.sina.api.data.protobuf.CommentWrap$Comment  

    19:          4273       34273568  [Ljava.util.HashMap$Entry;  

    20:        459983       33118776  cn.abc.data.protobuf.AbcMessageWrap$AbcMessage  

    21:        458776       22021248  java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask  

    22:        458776       22021248  java.util.concurrent.FutureTask$Sync  

    23:       1314416       21030656  com.google.protobuf.UnknownFieldSet  

     24:        459982       11039568  cn.sina.datapush.notifier.core.DispatcherBase$MessageProcessor  

     25:        458776       11010624  java.util.concurrent.Executors$RunnableAdapter  

     26:        458776        7340416  cn.abc.datapush.notifier.core.DispatcherBase$MessageProcessor$1  

     27:         40897        5909152  <constMethodKlass>  

     28:         40897        4917592  <methodKlass>  

     29:          3193        3748688  <constantPoolKlass>  

     30:         62093        3274344  <symbolKlass>  

   排名前幾位的都是ByteCharStringInteger之類的,不要灰心,繼續往下看,后面會出現一些有趣的對象。第22位發現了45萬個FutureTask,很顯然這是不正常的。應該是某線程響應過慢,造成待處理任務出現了堆積。查看代碼,果然處理線程只有4條,大量的請求得不到響應。通過gc分析,每5秒鍾會產生100M左右的對象得不到處理,所以JVM heap很快就被耗盡。將線程數改為36條,問題立刻得到了解決。

 

  (4)檢查目前cpu占用情況,top -H,然后按“1”,會看到當前進程中每個線程所占CPU的比例。注意觀察前幾名,然后jstack -l vmid > jstack.log打出線程堆棧,看看是什么線程占用了CPU。這里需要注意的是,top -H顯示的線程id是十進制,而jstack打出的線程堆棧是16進制。看看那些最忙的thread是不是那些真正應該忙的thread,如果是一些黑馬線程,則要考慮是否是代碼有死循環或者是意外的問題。

 

分析源代碼

  分析源代碼是最有技術含量的事情,也是比較耗時而且不見得有效果的事情。所以我把源碼分析放到解決線上問題的最后一步,因為必須要做到有的放矢。帶着問題去分析代碼,會比較容易。通過20%代碼的修改,就可以解決80%的性能問題。比如上面這個線上問題,肯定是線程處理慢造成的問題。需要針對線程的調用,同步異步等進行分析。

 


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM