線上內存溢出問題排查案例

1.遇到問題？java

如今問題反饋加固服務使用一段時間以後，前置向平臺拉取策略失敗，排查加固日誌服務看着是正常運行，有些error日誌只是socket連接斷開的錯誤，操做管理平臺頁面發現頁面功能沒法使用，重啓服務後恢復正常，由此判斷服務出現宕機假死現象。mysql

2.處理思路？sql

由於根據日誌已經沒法肯定具體形成服務宕機的具體緣由，對於目前遇到的狀況猜想服務中發生了死鎖或是內存溢出，因而在問題發生時抓取了服務中心異常線程的堆棧信息和內存快照分析問題。數據庫

3.實例說明?apache

a.查看Java進程 jps -lvm服務器

[root@xdja ~]# jps -lvm網絡

25501 org.apache.catalina.startup.Bootstrap start -=/usr/local/oldTomcat-topsec/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djdk.tls.ephemeralDHKeySize=2048 -Djava.endorsed.dirs=/usr/local/oldTomcat-topsec/endorsed -Dcatalina.base=/usr/local/oldTomcat-topsec -Dcatalina.home=/usr/local/oldTomcat-topsec -Djava.io.tmpdir=/usr/local/oldTomcat-topsec/tempjvm

注意：socket

現場服務器不少都是使用OpenJdk不支持以下命令，能夠經過下載解壓jdk到bin目錄下執行命令便可。工具

b.查看Java進程服務下各個線程的cpu使用狀況 top -Hp pid

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND

25394 root 20 0 12.393g 964220 14248 S 0.0 3.0 0:00.00 java

25395 root 20 0 12.393g 964220 14248 S 0.0 3.0 0:00.46 java

25396 root 20 0 12.393g 964220 14248 S 0.0 3.0 0:00.08 java

25397 root 20 0 12.393g 964220 14248 S 0.0 3.0 0:00.09 java

25398 root 20 0 12.393g 964220 14248 S 0.0 3.0 0:00.08 java

c.找到cup佔用高的線程pid轉爲16進制的新的pid（好比是：0x7ab9）

printf "%x\n" pid =16進制的新的pid

d.查看到該線程的堆棧信息 jstack 服務進程id |grep 0x7ab9 -A 100>aa.txt將指定異常線程信息輸出到文件中

或者jstack pid>aa.txt輸出整個項目進程信息

2020-05-20 09:39:13 Full thread dump Java HotSpot(TM) 64-Bit Server VM (24.71-b01 mixed mode):

"Thread-1467" prio=10 tid=0x00007f022c003000 nid=0x7b3e runnable [0x00007f0286475000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:152) at java.net.SocketInputStream.read(SocketInputStream.java:122) at java.io.BufferedInputStream.fill(BufferedInputStream.java:235) at java.io.BufferedInputStream.read1(BufferedInputStream.java:275) at java.io.BufferedInputStream.read(BufferedInputStream.java:334) - locked <0x00000007ff931fa0> (a java.io.BufferedInputStream) at com.xdja.topsec.socket.server.BSThread.run(BSThread.java:46)

"Attach Listener" daemon prio=10 tid=0x00007f024c001000 nid=0x6c4e waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE

"topsecTaskExecutor-10" prio=10 tid=0x00007f0188003000 nid=0x56cf waiting on condition [0x00007f0284359000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method)

parking to wait for <0x00000006c13ddd18> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)

at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1085)

at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)

at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:745)

"topsecTaskExecutor-9" prio=10 tid=0x00007f01f0137800 nid=0x56c7 waiting on condition [0x00007f0284657000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method)
parking to wait for <0x00000006c13ddd18> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
- at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
  
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1079)
  
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)
  
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
  
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
  
  at java.lang.Thread.run(Thread.java:745)

"topsecTaskExecutor-8" prio=10 tid=0x00007f0188001800 nid=0x56be waiting on condition [0x00007f0284758000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method)

- parking to wait for <0x00000006c13ddd18> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)

at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)

at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1085)

at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)

at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

at java.lang.Thread.run(Thread.java:745)

"Abandoned connection cleanup thread" daemon prio=10 tid=0x00007f029c3d5000 nid=0x563e in Object.wait() [0x00007f0286576000] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method)

waiting on <0x00000006c17e04b0> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)

locked <0x00000006c17e04b0> (a java.lang.ref.ReferenceQueue$Lock) at com.mysql.jdbc.AbandonedConnectionCleanupThread.run(AbandonedConnectionCleanupThread.java:64) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:745)

"Finalizer" daemon prio=10 tid=0x00007f029c077800 nid=0x5629 in Object.wait() [0x00007f0295320000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method)

waiting on <0x00000006c0010e80> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)

locked <0x00000006c0010e80> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

註釋：

1.死鎖，Deadlock（重點關注）

2.執行中，Runnable

3.等待資源，Waiting on condition（重點關注）

4.等待獲取監視器，Waiting on monitor entry（重點關注）

5.暫停，Suspended

6.對象等待中，Object.wait() 或 TIMED_WAITING

7.阻塞，Blocked（重點關注）

8.中止，Parked

含義以下所示：

Deadlock：死鎖線程，通常指多個線程調用間，進入相互資源佔用，致使一直等待沒法釋放的狀況。

Runnable：通常指該線程正在執行狀態中，該線程佔用了資源，正在處理某個請求，有可能正在傳遞SQL到數據庫執行，有可能在對某個文件操做，有可能進行數據類型等轉換。

Waiting on condition：等待資源，或等待某個條件的發生。具體緣由需結合 stacktrace來分析。一種狀況是網絡很是忙，幾乎消耗了全部的帶寬，仍然有大量數據等待網絡讀寫；另外一種狀況也多是網絡空閒，但因爲路由等問題，致使包沒法正常的到達。
若是堆棧信息明確是應用代碼，則證實該線程正在等待資源。通常是大量讀取某資源，且該資源採用了資源鎖的狀況下，線程進入等待狀態，等待資源的讀取。又或者，正在等待其餘線程的執行等。

若是發現有大量的線程都在處在 Wait on condition，從線程 stack看，正等待網絡讀寫，這多是一個網絡瓶頸的徵兆。由於網絡阻塞致使線程沒法執行。另一種出現 Wait on condition的常見狀況是該線程在 sleep，
等待 sleep的時間到了時候，將被喚醒。 Blocked：線程阻塞，是指當前線程執行過程當中，所須要的資源長時間等待卻一直未能獲取到，被容器的線程管理器標識爲阻塞狀態，能夠理解爲等待資源超時的線程。

Waiting for monitor entry 和 in Object.wait()：Monitor 是 Java中用以實現線程之間的互斥與協做的主要手段，它能夠當作是對象或者 Class的鎖。每個對象都有，也僅有一個 monitor。從下圖1中能夠看出，每一個 Monitor在某個時刻，
只能被一個線程擁有，該線程就是「Active Thread」，而其它線程都是「Waiting Thread」，分別在兩個隊列「 Entry Set」和「Wait Set」裏面等候。在「Entry Set」中等待的線程狀態是「Waiting for monitor entry」，
而在「Wait Set」中等待的線程狀態是「in Object.wait()」。

1）waiting on <0x00000006c17e04b0> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
- locked <0x00000006c17e04b0> (a java.lang.ref.ReferenceQueue$Lock) at com.mysql.jdbc.AbandonedConnectionCleanupThread.run(AbandonedConnectionCleanupThread.java:64) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:745)
- 1）線程狀態是Blocked，阻塞狀態。說明線程等待資源超時！
2）「waiting to lock <0x00000000acf4d0c0>」指，線程在等待給這個 0x00000000acf4d0c0 地址上鎖3）在

3）「waiting for monitor entry」說明此線程經過 synchronized(obj) {……} 申請進入了臨界區，從而進入了下圖1中的「Entry Set」隊列，但該 obj 對應的 monitor 被其餘線程擁有，因此本線程在 Entry Set 隊列中等待。

4）第一行裏，"RMI TCP Connection(267865)-172.16.5.25"是 Thread Name 。tid指Java Thread id。nid指native線程的id。prio是線程優先級。[0x00007fd4f8684000]是線程棧起始地址。

綜合示範二：Waiting on condition 和 TIMED_WAITING

實例以下：

Thread-6" prio=10 tid=0x00007f029cc66800 nid=0x5634 waiting on condition [0x00007f02873e3000] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at com.xdja.topsec.socket.handler.SysCsHandler.sendAllUrlOfAllSn(SysCsHandler.java:40) at com.xdja.topsec.socket.server.SysCsThread.run(SysCsThread.java:24)1）

「TIMED_WAITING (parking)」中的 timed_waiting 指等待狀態，但這裏指定了時間，自身項目中多處線程用到了sleep。

「TIMED_WAITING (on object monitor)」，對於本例而言，是由於本線程調用了 java.lang.Object.wait(long timeout) 而進入等待狀態。

「Wait Set」中等待的線程狀態就是「in Object.wait() 」。當線程得到了 Monitor，進入了臨界區以後，若是發現線程繼續運行的條件沒有知足，它則調用對象（通常就是被 synchronized 的對象）的 wait() 方法，放棄了 Monitor，進入「Wait Set」隊列。只有當別的線程在該對象上調用了 notify() 或者 notifyAll() ，「 Wait Set」隊列中線程才獲得機會去競爭，可是隻有一個線程得到對象的 Monitor，恢復到運行態。

對於以上信息排查沒有發現服務中出現死鎖現象因而轉向內存使用排查。

5.查看內存佔用高的線程快照信息

獲取JVM參數配置及當前使用狀況信息：jmap -heap pid

using thread-local object allocation. Parallel GC with 8 thread(s)

Heap Configuration:

MinHeapFreeRatio = 0

MaxHeapFreeRatio = 100

MaxHeapSize = 5368709120 (5120.0MB)

NewSize = 1310720 (1.25MB)

MaxNewSize = 17592186044415 MB

OldSize = 5439488 (5.1875MB)

NewRatio = 2

SurvivorRatio = 8

PermSize = 134217728 (128.0MB)

MaxPermSize = 268435456 (256.0MB)

G1HeapRegionSize = 0 (0.0MB)

Heap Usage:

PS Young Generation

Eden Space:

capacity = 1783627776 (1701.0MB)

used = 1783627776 (1701.0MB)

free = 0 (0.0MB) 100.0% used

From Space:

capacity = 3145728 (3.0MB)

used = 0 (0.0MB)

free = 3145728 (3.0MB) 0.0%used

To Space:

capacity = 3145728 (3.0MB)

used = 0 (0.0MB)

free = 3145728 (3.0MB) 0.0% used

PS Old Generation

capacity = 3578789888 (3413.0MB)

used = 3578654856 (3412.871223449707MB)

free = 135032 (0.12877655029296875MB) 99.99622688103449%used

PS Perm Generation

capacity = 134217728 (128.0MB)

used = 52435368 (50.006263732910156MB)

free = 81782360 (77.99373626708984MB)

39.06739354133606% used

27553 interned Strings occupying 3230968 bytes.

由此能夠看出Eden已經內存使用100%這樣就會把內存較大的對象放入Old Generation

當old區使用到峯值時就致使了Fgc會致使整個業務沒法正常使用。此時能夠經過調整yong區的

參數通常是佔用1/3jvm內存，這樣能夠減小fgc的次數和時間提升系統穩定性。

獲取內存中全部實例及大小：jmap -histo pid

num #instances #bytes class name

1: 6092078 5181006784 [B

2: 6057175 145372200 java.util.concurrent.ConcurrentLinkedQueue$Node

3: 91395 13623944 <constMethodKlass>

4: 129628 11938344 [C

5: 91395 11710064 <methodKlass>

6: 8119 9829080 <constantPoolKlass>

7: 8119 5940624 <instanceKlassKlass>

8: 6713 5421824 <constantPoolCacheKlass>

9: 125684 3016416 java.lang.String

10: 4207 2198744 <methodDataKlass>

11: 44205 2121840 org.jfaster.mango.parser.Token

12: 20820 1665600 java.lang.reflect.Method

13: 32642 1305680 java.util.LinkedHashMap$Entry

14: 11385 990832 [Ljava.util.HashMap$Entry;

15: 17313 969528 org.jfaster.mango.parser.ASTBlank

16: 17308 969248 org.jfaster.mango.parser.ASTText

17: 29001 928032 java.util.HashMap$Entry

18: 8726 850248 java.lang.Class

19: 26414 845248 java.util.concurrent.ConcurrentHashMap$HashEntry

20: 11436 738272 [S

21: 22050 705600 org.jfaster.mango.stat.atomic.LongAdder

能夠根據內存中的實例對象和佔用的內存信息做爲參考來優化本身的業務代碼

獲取內存快照信息：jmap -dump:format=b,file=tmp.hprof pid

a.獲取到內存快照文件後能夠經過Java自帶的jvisualvm.exe導入tmp.hprof文件查看相關信息

推薦使用IBM HeapAnalyzer工具排查

啓動IBM HeapAnalyzer：java -Xmx2g -jar .\ha457.jar

-Xmx2g爲啓動時分配內存參數

HeapAnalyzer啓動後，經過菜單File->Open打開生成的dump文件tmp.hprof。

dump文件加載後，經過菜單Analysis->Tree View展示出來。

經過dump信息分析內存泄漏的對象。主要思路是堆內存佔用比例，比例越大說明堆內存消耗越多。

這個例子很簡單，經過以下圖很快就可定位出內存泄漏的地方。

由此能夠看出java/util/concurrent/ConcurrentLinkedQueue$Node

ConcurrentLinkedQueue對象佔用了5個多G的內存已經佔用了99%的Java內存這樣就會致使

發生Fgc或者內存溢出致使整個系統假死。

6.解決方案

優化業務代碼減小內存開銷

使用Redis中間件替換隊列