[[403756]]

最近工作又遇到幾次線上告警的問(wèn)題，排查基本上就是cup100%以及內(nèi)存OOM問(wèn)題，再分享一下之前遇到這類問(wèn)題排查的一些思路和過(guò)程，希望對(duì)你有所幫助，感謝你的閱讀。

問(wèn)題現(xiàn)象

【告警通知-應(yīng)用異常告警】

簡(jiǎn)單看下告警的信息：拒絕連接，反正就是服務(wù)有問(wèn)題了，請(qǐng)不要太在意馬賽克。

環(huán)境說(shuō)明

Spring Cloud F版。

項(xiàng)目中默認(rèn)使用 spring-cloud-sleuth-zipkin 依賴得到 zipkin-reporter。分析的版本發(fā)現(xiàn)是 zipkin-reporter版本是 2.7.3 。

<dependency> 
 <groupId>org.springframework.cloud</groupId> 
 <artifactId>spring-cloud-sleuth-zipkin</artifactId> 
</dependency> 

版本：2.0.0.RELEASE

版本說(shuō)明

問(wèn)題排查

通過(guò)告警信息，知道是哪一臺(tái)服務(wù)器的哪個(gè)服務(wù)出現(xiàn)問(wèn)題。首先登錄服務(wù)器進(jìn)行檢查。

1、檢查服務(wù)狀態(tài)和驗(yàn)證健康檢查URL是否ok

“這一步可忽略/跳過(guò)，與實(shí)際公司的的健康檢查相關(guān)，不具有通用性。

①查看服務(wù)的進(jìn)程是否存在。

“ps -ef | grep 服務(wù)名 ps -aux | grep 服務(wù)名

②查看對(duì)應(yīng)服務(wù)健康檢查的地址是否正常，檢查 ip port 是否正確

“是不是告警服務(wù)檢查的url配置錯(cuò)了，一般這個(gè)不會(huì)出現(xiàn)問(wèn)題

③驗(yàn)證健康檢查地址

“這個(gè)健康檢查地址如：http://192.168.1.110:20606/serviceCheck 檢查 IP 和 Port 是否正確。

# 服務(wù)正常返回結(jié)果 
curl http://192.168.1.110:20606/serviceCheck 
{"appName":"test-app","status":"UP"} 
 
# 服務(wù)異常，服務(wù)掛掉 
curl http://192.168.1.110:20606/serviceCheck 
curl: (7) couldn't connect to host 

2、查看服務(wù)的日志

查看服務(wù)的日志是否還在打印，是否有請(qǐng)求進(jìn)來(lái)。查看發(fā)現(xiàn)服務(wù)OOM了。

OOM錯(cuò)誤

tips：java.lang.OutOfMemoryError GC overhead limit exceeded

oracle官方給出了這個(gè)錯(cuò)誤產(chǎn)生的原因和解決方法：Exception in thread thread_name: java.lang.OutOfMemoryError: GC Overhead limit exceeded Cause: The detail message "GC overhead limit exceeded" indicates that the garbage collector is running all the time and Java program is making very slow progress. After a garbage collection, if the Java process is spending more than approximately 98% of its time doing garbage collection and if it is recovering less than 2% of the heap and has been doing so far the last 5 (compile time constant) consecutive garbage collections, then a java.lang.OutOfMemoryError is thrown. This exception is typically thrown because the amount of live data barely fits into the Java heap having little free space for new allocations. Action: Increase the heap size. The java.lang.OutOfMemoryError exception for GC Overhead limit exceeded can be turned off with the command line flag -XX:-UseGCOverheadLimit.

原因：大概意思就是說(shuō)，JVM花費(fèi)了98%的時(shí)間進(jìn)行垃圾回收，而只得到2%可用的內(nèi)存，頻繁的進(jìn)行內(nèi)存回收(最起碼已經(jīng)進(jìn)行了5次連續(xù)的垃圾回收)，JVM就會(huì)曝出ava.lang.OutOfMemoryError: GC overhead limit exceeded錯(cuò)誤。

上面tips來(lái)源：java.lang.OutOfMemoryError GC overhead limit exceeded原因分析及解決方案

3、檢查服務(wù)器資源占用狀況

查詢系統(tǒng)中各個(gè)進(jìn)程的資源占用狀況，使用 top 命令。查看出有一個(gè)進(jìn)程為 11441 的進(jìn)程 CPU 使用率達(dá)到300%，如下截圖：

CPU爆表

然后 查詢這個(gè)進(jìn)程下所有線程的CPU使用情況：

top -H -p pid 保存文件：top -H -n 1 -p pid > /tmp/pid_top.txt

# top -H -p 11441 
PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND 
11447 test    20   0 4776m 1.6g  13m R 92.4 20.3  74:54.19 java 
11444 test    20   0 4776m 1.6g  13m R 91.8 20.3  74:52.53 java 
11445 test    20   0 4776m 1.6g  13m R 91.8 20.3  74:50.14 java 
11446 test    20   0 4776m 1.6g  13m R 91.4 20.3  74:53.97 java 
.... 

查看 PID：11441 下面的線程，發(fā)現(xiàn)有幾個(gè)線程占用cpu較高。

4、保存堆棧數(shù)據(jù)

1、打印系統(tǒng)負(fù)載快照

top -b -n 2 > /tmp/top.txt 
 
top -H -n 1 -p pid > /tmp/pid_top.txt 

2、cpu升序打印進(jìn)程對(duì)應(yīng)線程列表

ps -mp-o THREAD,tid,time | sort -k2r > /tmp/進(jìn)程號(hào)_threads.txt 

3、看tcp連接數(shù) (最好多次采樣)

lsof -p 進(jìn)程號(hào) > /tmp/進(jìn)程號(hào)_lsof.txt 
lsof -p 進(jìn)程號(hào) > /tmp/進(jìn)程號(hào)_lsof2.txt 

4、查看線程信息 (最好多次采樣)

jstack -l 進(jìn)程號(hào) > /tmp/進(jìn)程號(hào)_jstack.txt  
jstack -l 進(jìn)程號(hào) > /tmp/進(jìn)程號(hào)_jstack2.txt 
jstack -l 進(jìn)程號(hào) > /tmp/進(jìn)程號(hào)_jstack3.txt 

5、查看堆內(nèi)存占用概況

jmap -heap 進(jìn)程號(hào) > /tmp/進(jìn)程號(hào)_jmap_heap.txt 

6、查看堆中對(duì)象的統(tǒng)計(jì)信息

jmap -histo 進(jìn)程號(hào) | head -n 100 > /tmp/進(jìn)程號(hào)_jmap_histo.txt 

7、查看GC統(tǒng)計(jì)信息

jstat -gcutil 進(jìn)程號(hào) > /tmp/進(jìn)程號(hào)_jstat_gc.txt 

8、生產(chǎn)對(duì)堆快照Heap dump

jmap -dump:format=b,file=/tmp/進(jìn)程號(hào)_jmap_dump.hprof 進(jìn)程號(hào) 

“堆的全部數(shù)據(jù)，生成的文件較大。

jmap -dump:live,format=b,file=/tmp/進(jìn)程號(hào)_live_jmap_dump.hprof 進(jìn)程號(hào)

“dump:live,這個(gè)參數(shù)表示我們需要抓取目前在生命周期內(nèi)的內(nèi)存對(duì)象，也就是說(shuō)GC收不走的對(duì)象，一般用這個(gè)就行。

拿到出現(xiàn)問(wèn)題的快照數(shù)據(jù)，然后重啟服務(wù)。

問(wèn)題分析

根據(jù)上述的操作，已經(jīng)獲取了出現(xiàn)問(wèn)題的服務(wù)的GC信息、線程堆棧、堆快照等數(shù)據(jù)。下面就進(jìn)行分析，看問(wèn)題到底出在哪里。

1、分析cpu占用100%的線程

轉(zhuǎn)換線程ID

從jstack生成的線程堆棧進(jìn)程分析。

將 上面線程ID 為

11447 ：0x2cb7 
 
11444 ：0x2cb4 
 
11445 ：0x2cb5 
 
11446 ：0x2cb6 

轉(zhuǎn)為 16進(jìn)制(jstack命令輸出文件記錄的線程ID是16進(jìn)制)。

第一種轉(zhuǎn)換方法 :

$ printf “0x%x” 11447 
 
“0x2cb7” 

第二種轉(zhuǎn)換方法 : 在轉(zhuǎn)換的結(jié)果加上 0x即可。

查找線程堆棧

$ cat 11441_jstack.txt | grep "GC task thread" 
"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f971401e000 nid=0x2cb4 runnable 
"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f9714020000 nid=0x2cb5 runnable 
"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007f9714022000 nid=0x2cb6 runnable 
"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007f9714023800 nid=0x2cb7 runnable 

發(fā)現(xiàn)這些線程都是在做GC操作。

2、分析生成的GC文件

S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT    
 0.00   0.00 100.00  99.94  90.56  87.86    875    9.307  3223 5313.139 5322.446 

• S0：幸存1區(qū)當(dāng)前使用比例
• S1：幸存2區(qū)當(dāng)前使用比例
• E：Eden Space(伊甸園)區(qū)使用比例
• O：Old Gen(老年代)使用比例
• M：元數(shù)據(jù)區(qū)使用比例
• CCS：壓縮使用比例
• YGC：年輕代垃圾回收次數(shù)
• FGC：老年代垃圾回收次數(shù)
• FGCT：老年代垃圾回收消耗時(shí)間
• GCT：垃圾回收消耗總時(shí)間

FGC 十分頻繁。

3、分析生成的堆快照

使用 Eclipse Memory Analyzer 工具。下載地址：https://www.eclipse.org/mat/downloads.php

分析的結(jié)果：

看到堆積的大對(duì)象的具體內(nèi)容：

問(wèn)題大致原因，InMemoryReporterMetrics 引起的OOM。

zipkin2.reporter.InMemoryReporterMetrics @ 0xc1aeaea8 
 
Shallow Size: 24 B Retained Size: 925.9 MB 

也可以使用：Java內(nèi)存Dump(https://www.perfma.com/docs/memory/memory-start)進(jìn)行分析，如下截圖，功能沒(méi)有MAT強(qiáng)大，有些功能需收費(fèi)。

4、原因分析和驗(yàn)證

因?yàn)槌霈F(xiàn)了這個(gè)問(wèn)題，查看出現(xiàn)問(wèn)題的這個(gè)服務(wù) zipkin的配置，和其他服務(wù)沒(méi)有區(qū)別。發(fā)現(xiàn)配置都一樣。

然后看在試著對(duì)應(yīng)的 zipkin 的jar包，發(fā)現(xiàn)出現(xiàn)問(wèn)題的這個(gè)服務(wù)依賴的 zipkin版本較低。

有問(wèn)題的服務(wù)的 zipkin-reporter-2.7.3.jar

其他沒(méi)有問(wèn)題的服務(wù) 依賴的包 ：zipkin-reporter-2.8.4.jar

將有問(wèn)題的服務(wù)依賴的包版本升級(jí)，在測(cè)試環(huán)境進(jìn)行驗(yàn)證，查看堆棧快照發(fā)現(xiàn)沒(méi)有此問(wèn)題了。

原因探索

查 zipkin-reporter的 github：搜索 相應(yīng)的資料

https://github.com/openzipkin/zipkin-reporter-java/issues?q=InMemoryReporterMetrics

找到此 下面這個(gè)issues：

https://github.com/openzipkin/zipkin-reporter-java/issues/139

修復(fù)代碼和驗(yàn)證代碼：

https://github.com/openzipkin/zipkin-reporter-java/pull/119/files

對(duì)比兩個(gè)版本代碼的差異：

簡(jiǎn)單的DEMO驗(yàn)證：

// 修復(fù)前的代碼： 
  private final ConcurrentHashMap<Throwable, AtomicLong> messagesDropped = 
      new ConcurrentHashMap<Throwable, AtomicLong>(); 
// 修復(fù)后的代碼： 
  private final ConcurrentHashMap<Class<? extends Throwable>, AtomicLong> messagesDropped = 
      new ConcurrentHashMap<>(); 

修復(fù)后使用 這個(gè)key ：Class 替換 Throwable。

簡(jiǎn)單驗(yàn)證：

解決方案

將zipkin-reporter 版本進(jìn)行升級(jí)即可。使用下面依賴配置，引入的 zipkin-reporter版本為 2.8.4 。

<!-- zipkin 依賴包 --> 
<dependency> 
  <groupId>io.zipkin.brave</groupId> 
  <artifactId>brave</artifactId> 
  <version>5.6.4</version> 
</dependency> 

小建議：配置JVM參數(shù)的時(shí)候還是加上下面參數(shù),設(shè)置內(nèi)存溢出的時(shí)候輸出堆?？煺?

-XX:+HeapDumpOnOutOfMemoryError  
 -XX:HeapDumpPath=path/filename.hprof  
  

參考文章

記一次sleuth發(fā)送zipkin異常引起的OOM

https://www.jianshu.com/p/f8c74943ccd8

本文轉(zhuǎn)載自微信公眾號(hào)「Java編程技術(shù)樂(lè)園」，可以通過(guò)以下二維碼關(guān)注。轉(zhuǎn)載本文請(qǐng)聯(lián)系Java編程技術(shù)樂(lè)園公眾號(hào)。