2. 程式人生 > 程式設計 >一次非典型的CPU告警的排查

一次非典型的CPU告警的排查

阿新 • • 發佈：2019-12-31

最近線上頻繁收到CPU超過閾值的告警,很明顯是哪裡出了問題. 於是排查了一番,到最後找到罪魁禍首的時候,突然意識到這次是一次很有意思的"非典型"的CPU的問題,所以這裡特意記錄一下.

為啥說它是非典型呢,因為在我的經驗裡,典型的CPU飆升通常都是業務程式碼裡面有死迴圈,或是某個RPC效能過低阻塞了大量執行緒等等,而這次的CPU問題卻是由GC引起的,因吹斯汀

來看看排查過程

找出佔用CPU的執行緒

top

首先肯定是先看哪些執行緒佔用CPU最高,這個可以使用top命令:

top -Hp $pid -b -n 1|sed -n "7,17p"

   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND           
 94349 app     20   0 11.2g 5.0g  12m S 15.0 32.1 215:03.69 java              
 94357 app     20   0 11.2g 5.0g  12m S 15.0 32.1  88:22.39 java              
 94352 app     20   0 11.2g 5.0g  12m S 13.1 32.1 215:05.71 java              
 94350 app     20   0 11.2g 5.0g  12m S 11.2 32.1 215:04.86 java              
 94351 app     20   0 11.2g 5.0g  12m S 11.2 32.1 215:04.99 java              
 94935 app     20   0 11.2g 5.0g  12m S 11.2 32.1  63:11.75 java              
 94926 app     20   0 11.2g 5.0g  12m S  9.4 32.1  63:10.58 java              
 94927 app     20   0 11.2g 5.0g  12m S  5.6 32.1  63:06.89 java              
 94932 app     20   0 11.2g 5.0g  12m S  5.6 32.1  63:12.65 java              
 94939 app     20   0 11.2g 5.0g  12m S  5.6 32.1  63:01.75 java  
複製程式碼

$pid是我們對應的java程式的程式ID,sed -n "7,17p" 是取第7到第17行,因為前7行都是top命令的頭部資訊,所以第7到第17行就是該執行緒下最耗CPU的前10個執行緒了.

其中第一列的"pid"就是JVM裡面對應的執行緒ID,我們只需要用執行緒ID在jstack裡面找到對應的執行緒就知道是誰在搞鬼了.

不過需注意的是top命令中的PID是十進位制的,而jstack裡面的執行緒ID是十六進位制的,所以我們還需要做一個工作,就是把上面的PID轉成十六進位制,這裡我只轉換了最耗CPU的前3個:

[app@linux-v-l-02:/app/tmp/]$printf '%x\n' 94349
1708d
[app@linux-v-l
 
-02:/app/tmp/]$printf '%x\n' 94357
17095
[app@linux-v-l-02:/app/tmp/]$printf '%x\n' 94352
17090

複製程式碼
jstack

現在我們已經知道消耗CPU的執行緒ID,接著就要去看看這些執行緒ID對應的是什麼執行緒.

首先使用jstack打出JVM裡面的所有的執行緒資訊:

[app@linux-v-l-02:/app/tmp/]jstack -l $pid >>/tmp/jstack.txt
複製程式碼

值得一提的是,由於JVM裡面的執行緒一直在變化,而TOP中的執行緒也一直在變化,所以如果jstack命令和top命令是分開執行的話,很有可能兩者的執行緒ID會對應不上. 因此top命令和jstack命令最好是寫好指令碼一起執行. 其實我就是寫指令碼一起執行的~

接著,看看1708d,17095,17090 這三個到底是什麼執行緒:

[app@linux-v-l-02:/app/tmp/]$egrep "1708d|17095|17090" jstack.txt --color
"Gang worker#0 (Parallel GC Threads)" os_prio=0 tid=0x00007f4d4c023000 nid=0x1708d runnable 
"Gang worker#3 (Parallel GC Threads)" os_prio=0 tid=0x00007f4d4c028800 nid=0x17090 runnable 
"G1 Concurrent Refinement Thread#0" os_prio=0 tid=0x00007f4d4c032000 nid=0x17095 runnable 
複製程式碼

上面的nid就是對應的十六進位制的執行緒ID. 從jstack可以看出,居然最耗CPU的執行緒都是一些GC執行緒.

對JVM的FULL GC我們是有監控的,這個應用自從換了G1之後,一般一週左右才會發生一次FULL GC,所以我們一直都以為我們的JVM堆是很健康的,但很種種跡象表明,我們的JVM確實是出問題了

GC問題

gc日誌

GC日誌我們是一直有列印,開啟一看,果然是有非常多的GC pause,如下

2019-08-12T20:12:23.002+0800: 501598.612: [GC pause (G1 Humongous Allocation) (young) (initial-mark),0.0907586 secs]
   [Parallel Time: 84.5 ms,GC Workers: 4]
      [GC Worker Start (ms): Min: 501598615.0,Avg: 501598615.0,Max: 501598615.0,Diff: 0.1]
      [Ext Root Scanning (ms): Min: 4.9,Avg: 5.0,Max: 5.0,Diff: 0.2,Sum: 19.8]
      [Update RS (ms): Min: 76.6,Avg: 76.7,Max: 76.7,Diff: 0.1,Sum: 306.7]
         [Processed Buffers: Min: 945,Avg: 967.0,Max: 1007,Diff: 62,Sum: 3868]
      [Scan RS (ms): Min: 0.0,Avg: 0.0,Max: 0.0,Diff: 0.0,Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0,Sum: 0.0]
      [Object Copy (ms): Min: 2.4,Avg: 2.5,Max: 2.6,Sum: 9.8]
      [Termination (ms): Min: 0.0,Sum: 0.0]
         [Termination Attempts: Min: 1,Avg: 1.0,Max: 1,Diff: 0,Sum: 4]
      [GC Worker Other (ms): Min: 0.0,Avg: 0.1,Max: 0.1,Sum: 0.3]
      [GC Worker Total (ms): Min: 84.2,Avg: 84.2,Max: 84.2,Sum: 336.7]
      [GC Worker End (ms): Min: 501598699.2,Avg: 501598699.2,Max: 501598699.2,Diff: 0.0]
   [Code Root Fixup: 0.2 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 5.9 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.3 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.7 ms]
      [Free CSet: 0.2 ms]
   [Eden: 230.0M(1968.0M)->0.0B(1970.0M) Survivors: 8192.0K->8192.0K Heap: 1693.6M(4096.0M)->1082.1M(4096.0M)]
 [Times: user=0.34 sys=0.00,real=0.10 secs] 
2019-08-12T20:12:23.094+0800: 501598.703: [GC concurrent-root-region-scan-start]
2019-08-12T20:12:23.101+0800: 501598.711: [GC concurrent-root-region-scan-end,0.0076353 secs]
2019-08-12T20:12:23.101+0800: 501598.711: [GC concurrent-mark-start]
2019-08-12T20:12:23.634+0800: 501599.243: [GC concurrent-mark-end,0.5323465 secs]
2019-08-12T20:12:23.639+0800: 501599.249: [GC remark 2019-08-12T20:12:23.639+0800: 501599.249: [Finalize Marking,0.0019652 secs] 2019-08-12T20:12:23.641+0800: 501599.251: [GC ref-proc,0.0027393 secs] 2019-08-12T20:12:23.644+0800: 501599.254: [Unloading,0.0307159 secs],0.0366784 secs]
 [Times: user=0.13 sys=0.00,real=0.04 secs] 
2019-08-12T20:12:23.682+0800: 501599.291: [GC cleanup 1245M->1226M(4096M),0.0041762 secs]
 [Times: user=0.02 sys=0.00,real=0.01 secs] 
2019-08-12T20:12:23.687+0800: 501599.296: [GC concurrent-cleanup-start]
2019-08-12T20:12:23.687+0800: 501599.296: [GC concurrent-cleanup-end,0.0000487 secs]
2019-08-12T20:12:30.022+0800: 501605.632: [GC pause (G1 Humongous Allocation) (young) (to-space exhausted),0.3849037 secs]
   [Parallel Time: 165.7 ms,GC Workers: 4]
      [GC Worker Start (ms): Min: 501605635.2,Avg: 501605635.2,Max: 501605635.3,Diff: 0.1]
      [Ext Root Scanning (ms): Min: 3.5,Avg: 3.8,Max: 4.4,Diff: 0.9,Sum: 15.2]
      [Update RS (ms): Min: 135.5,Avg: 135.8,Max: 136.0,Diff: 0.5,Sum: 543.3]
         [Processed Buffers: Min: 1641,Avg: 1702.2,Max: 1772,Diff: 131,Sum: 6809]
      [Scan RS (ms): Min: 1.5,Avg: 1.6,Max: 1.6,Sum: 6.2]
      [Code Root Scanning (ms): Min: 0.0,Sum: 0.0]
      [Object Copy (ms): Min: 24.1,Avg: 24.4,Max: 24.6,Diff: 0.4,Sum: 97.4]
      [Termination (ms): Min: 0.0,Sum: 0.1]
         [Termination Attempts: Min: 1,Sum: 0.1]
      [GC Worker Total (ms): Min: 165.6,Avg: 165.6,Max: 165.6,Sum: 662.4]
      [GC Worker End (ms): Min: 501605800.8,Avg: 501605800.9,Max: 501605800.9,Diff: 0.0]
   [Code Root Fixup: 0.2 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 218.7 ms]
      [Evacuation Failure: 210.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.5 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.3 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 2.2 ms]
      [Free CSet: 0.2 ms]
   [Eden: 666.0M(1970.0M)->0.0B(204.0M) Survivors: 8192.0K->0.0B Heap: 2909.5M(4096.0M)->1712.4M(4096.0M)]
 [Times: user=1.44 sys=0.00,real=0.39 secs] 
2019-08-12T20:12:32.225+0800: 501607.834: [GC pause (G1 Evacuation Pause) (mixed),0.0800708 secs]
   [Parallel Time: 74.8 ms,GC Workers: 4]
      [GC Worker Start (ms): Min: 501607835.5,Avg: 501607835.6,Max: 501607835.6,Diff: 0.1]
      [Ext Root Scanning (ms): Min: 3.7,Avg: 4.0,Diff: 0.6,Sum: 16.2]
      [Update RS (ms): Min: 67.8,Avg: 68.0,Max: 68.1,Diff: 0.3,Sum: 272.0]
         [Processed Buffers: Min: 863,Avg: 899.8,Max: 938,Diff: 75,Sum: 3599]
複製程式碼

G1的日誌有個不好的地方就是太多了,看得眼花繚亂,為了方便描述,我將上述GC日誌省略一些無意義的,濃縮為以下三段:

2019-08-12T20:12:23.002+0800: 501598.612: [GC pause (G1 Humongous Allocation) (young) (initial-mark),Diff: 0.1]
......
    
   [Eden: 230.0M(1968.0M)->0.0B(1970.0M) Survivors: 8192.0K->8192.0K Heap: 1693.6M(4096.0M)->1082.1M(4096.0M)]
 [Times: user=0.34 sys=0.00,Diff: 0.1]
......

   [Eden: 666.0M(1970.0M)->0.0B(204.0M) Survivors: 8192.0K->0.0B Heap: 2909.5M(4096.0M)->1712.4M(4096.0M)]
 [Times: user=1.44 sys=0.00,Diff: 0.1]
......

複製程式碼

這段日誌看著就清晰多了,首先從日誌裡面就能看出至少3個問題:

  1. 出現了mixed型別的Evacuation Pause
  2. 頻繁G1 Humongous Allocation導致的to-space exhausted,說明大量的大物件不斷地分配出來
  3. GC pause時間達到0.3849037 secs,這是我們最不可容忍的

另外還有一個更嚴重的問題這裡是看不出來的,就是類似的日誌非常頻繁! 高峰時期基本就是每2秒鐘打印出一次

jmap -histo

通過上面的GC日誌,我們基本可以判斷,是應用程式不斷地new一些大物件導致的.

那什麼是大物件呢?

一般情況就是區域性變數的List,通常可以通過jmap -histo來檢視堆內哪些物件佔用記憶體比較大,例項數是多少

所以,先通過jmap -histo $pid來看看堆疊裡面的物件分佈是如何的:


num   #instances  #bytes  class name
--------------------------------------------
1:       1120   1032796420   [B
2:     838370    105246813   [C
3:     117631     55348463   [I
4:     352652     31033457   java.lang.reflect.Method
5:     665505     13978410   java.lang.String
6:     198567     12368412   [Ljava.lang.Object
7:     268941      9467465   java.util.HashMap$Node
8:     268941      8064567   java.util.treeMap$Entry
9:     268941      7845665   java.lang.reflect.Field
10:    268941      7754771   [Ljava.util.HashMap$Node

....

複製程式碼

一般來說,如果運氣好,而且業務程式碼有問題的,通常能在jmap -histo裡面看到我們業務涉及到的類名的.

但是很可惜,這裡沒有.

然而,聰明的同學可能一眼就看出了這個堆其實是很有問題的.

我們看排行第一的[B (byte陣列),佔用了堆大小1032796420(1G左右),而instances卻只有1120多個,簡單地一相除,居然每個物件能有1M大小!

很明顯,這就是我們要找的大物件了,但是隻知道是一些byte陣列,並不知道是什麼陣列,所以還需要進一步排查

為什麼1M就是大物件了呢? 由於我們的堆只有4G大小,一般G1最大隻有2048個region,因此每個region的大小就是2M. G1在分配新生代的物件的記憶體空間時,發現這個物件大於region size的一半,就可以認為是大物件了,故而發生G1 Humongous Allocation

jmap -dump:format=b

使用jmap -dump:format=b,file=head.hprof $pid 命令可以把JVM的堆內容dump出來. dump出來後一般直接在命令列檢視是看不出什麼的,得下載到本地,藉助一些分析工具來進行分析. 可以有很多工具可以分析,例如jvisualvm,jprofile,MAT等等

這裡我用到的是jvisualvm,開啟jvisualvm==>檔案==>裝入==>選中我剛剛下載下來的head.hprof,然後再點選"類",再點選按大小排序,可以得到如下圖.

image

可以看出,堆裡面的byte陣列例項數佔比只有0.9%,記憶體大小佔比卻高達30%,說明每一個例項都是大物件.

接下來我們雙擊第一行的"byte[]" 檢視這些byte陣列的明細. 可以看很多的物件都是1048600byte,也就是剛好1M,不過這樣還是看不出這個陣列的內容,所以我們匯出這個陣列到本地,如下圖:

image

匯出後先用Sublime Text開啟看一下,如下圖

i
可以看到,這個陣列實際大小隻有1k左右(數前面的非0的數字的個數),後面都是一些無意義的0值.

雖然還無法確定這個陣列是什麼程式碼產生的,但是至少可以大概確定了問題產生的原因: 肯定是某處程式碼new了一個1048600大的byte陣列,而實際場景中這個byte陣列只需要1k左右即可,後面沒有填充的位都是預設的0值

最後證實一下我們的猜測,簡單的用

 String str= new String (bytearr,"UTF-8");
 System.out.println("str = [" + str + "]");
複製程式碼

把陣列內容打印出來,列印結果大概如下(我省略了大部分內容):

str = [p C0+org.apache.camel.impl.DefaultExchangeHolder�
exchangeIdinFaultFlagoutFaultFlag	exceptioninBodyoutBody	inHeaders
outHeaders
remoteOptRolefaceUrlversionfromIfromUserfailFaceUrl
.....

複製程式碼

再用相關的關鍵詞搜尋一下程式碼,最後找出了真凶:

       data = DefaultExchangeHolder.marshal(exchange,false);
       baos = new ByteArrayOutputStream(1048600);// 真凶在這裡
       hessianOut = new Hessian2Output(baos);
       hessianOut.startMessage();
       hessianOut.writeObject(data);
       hessianOut.completeMessage();
       hessianOut.flush();
       exchangeData = baos.toByteArray();
複製程式碼

ByteArrayOutputStream的構造方法

  public ByteArrayOutputStream(int size) {
        if (size < 0) {
            throw new IllegalArgumentException("Negative initial size: "
                                               + size);
        }
        buf = new byte[size];
    }
複製程式碼

其實就是在利用Hessian序列化之前,new了一個1M大小的byte陣列,導致了大量的大物件出現,而這個byte陣列只是作為一個buf來使用,而且大小不夠時會自動增長(The buffer automatically grows as data is written to it.),所以根本沒必要設定那麼大.

相關推薦

一次非典型的CPU告警的排查

最近線上頻繁收到CPU超過閾值的告警,很明顯是哪裡出了問題. 於是排查了一番,到最後找到罪魁禍首的時候,突然意識到這次是一次很有意思的\"非典型\"的CPU的問題,所以這裡特意記錄一下.

記一次golang程式CPU高的排查過程

前言 事情的起因是某天CTO突然和我說，生產環境的程式CPU有點高，關鍵是現在也沒什麼負載，同樣的程式碼在開發環境上CPU就低的多了。

記一次Spring @Transactional失效的排查過程

問題 壓力測試時發現生成了相同的序號,根據日誌分析發現select ... for update沒有鎖住某一行的資料,從而導致序號重複

記一次"記憶體洩露"排查過程

問題的發現 今天發現線上一個應用記憶體佔用非常高，但它的cpu使用率卻很低

記錄一次網站快照被劫持排查血淚史

背景 網站是 discuz 搭建的論壇；運營反饋近期網站百度收錄異常，有類似博**彩內容收錄。

資料庫char varchar nchar nvarchar，編碼Unicode，UTF8，GBK等，Sql語句中文前為什麼加N（一次線上資料儲存亂碼排查）

背景 公司有一個資料處理線，上面的資料經過不同環境處理，然後上線到正式庫。其中一個環節需要將資料進行處理然後匯入到另外一個庫(Sql Server)。這個處理的程式是老大用python寫的，處理完後進入另外一個庫後某些欄

一次goroutine洩露問題的排查定位思路

問題的發現 前段時間，我們一個基於libbeat開發的日誌採集服務經常發生OOM的告警，OOM的排查大都比較簡單，直接檢視目標容器的記憶體變化情況即可。如圖所示

記一次線上服務CPU 100%的處理過程

告警 正在開會，突然釘釘告警聲響個不停，同時市場人員反饋客戶在投訴系統登不進了，報504錯誤。檢視釘釘上的告警資訊，幾臺業務伺服器節點全部報CPU超過告警閾值，達100%。

記一次堆外記憶體洩漏排查過程

一、專案介紹 lz_rec_push_kafka_consume該專案通過kafka與演算法進行互動，通過push推薦平臺（lz_rec_push_platform）預生成訊息體。

記一次線上伺服器記憶體溢位排查

2019獨角獸企業重金招聘Python工程師標準>>> 首先，這臺伺服器是我們的列印伺服器，使用的是finereport7.0自帶的webreport程式

一次MySQL死鎖的排查記錄

前幾天線上收到一條告警郵件，生產環境MySQL操作發生了死鎖，郵件告警的提煉出來的SQL大致如下。

記一次kafka莫名其妙關閉問題排查

現象： FT走著走著，就沒了；一檢查，發現kafka沒了 排查： 先復現了一次，拿到server.log

記一次Oracle死鎖/阻塞排查

記一次Oracle死鎖/阻塞排查 Im_Coder關注 2019.01.15 17:59:53字數 269閱讀 2,861 1. 檢查資料庫確定 是否 真實存在死鎖，若有 哪臺機器哪個程式。

記一次dell伺服器記憶體告警故障

起因： 公司新採購了一批DDR 2666MHZ 記憶體使用到線上，機房運維小A負載擴容記憶體到一批DELL R740xd 伺服器上。這是一個簡單的工作，體力為主。剛剛吃完午飯接到專案組電話，催我回來處理大問題。一臺伺服器記憶體

一次詭異的記憶體洩露排查過程，背後原因令人深思

每天進步一點點，關注我們哦，每天分享測試技術文章 本文章出自【碼同學軟體測試】

記錄一次tcp_timestamps 線上問題的排查

我們的情況和這個朋友遇到的有點類似：https://blog.csdn.net/majianting/article/details/96476375

一次簡單的伺服器 cpu 佔用率高的快速排查實戰

一次簡單的伺服器 cpu 佔用率高的快速排查實戰原svchost病毒伺服器cputrouble shoot排錯前兩天，朋友遇到一個線上 cpu 佔用率很高的問題，我們倆一起快速定位並解決了這個問題。在徵求朋友同意後，特發此文分享整個

記一次JAVA程序導致Kubernetes節點CPU飆高的排查與解決

一、發現問題 在一次系統上線後，我們發現某幾個節點在長時間執行後會出現CPU持續飆升的問題，導致的結果就是Kubernetes叢集的這個節點會把所在的Pod進行驅逐（排程）；如果排程到同樣問題的節點上，也會出現Pod一直

一次線上MySQL死鎖告警原因排查

專案場景：一次線上MySQL死鎖告警原因排查 最近處理了一次線上資料告警，記錄一下。

記一次 生產cpu飆高問題排查

背景  2022-12-01日，早上8:56運維的同事發給我一張監控異常的圖片，圖片資訊顯示我負責的系統有一臺伺服器使用率超過了100%，並且持續時間已經超過10小時。