线上内存溢出问题排查案例

1. 遇到问题？

现在问题反馈加固服务使用一段时间之后，前置向平台拉取策略失败，排查加固日志服务看着是正常运行，有些 error 日志只是 socket 链接断开的错误，操作管理平台页面发现页面功能无法使用，重启服务后恢复正常，由此判断服务出现宕机假死现象。

2. 处理思路？

因为根据日志已经无法确定具体造成服务宕机的具体原因，对于目前遇到的情况猜测服务中发生了死锁或是内存溢出，于是在问题发生时抓取了服务中心异常线程的堆栈信息和内存快照分析问题。

3. 实例说明？

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/temp

注意：

现场服务器很多都是使用 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™ 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)atcom.mysql.jdbc.AbandonedConnectionCleanupThread.run(AbandonedConnectionCleanupThread.java:64)atjava.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)atjava.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)atjava.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)atjava.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 ()”。

“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)

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)atcom.mysql.jdbc.AbandonedConnectionCleanupThread.run(AbandonedConnectionCleanupThread.java:64)atjava.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)atjava.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

4: 129628 11938344 [C

5: 91395 11710064

6: 8119 9829080

7: 8119 5940624

8: 6713 5421824

9: 125684 3016416 java.lang.String

10: 4207 2198744

11: 44205 2121840 org.jfaster.mango.parser.Token
12: 20820 1665600 java.lang.reflect.Method
13: 32642 1305680 java.util.LinkedHashMap$Entry14:11385990832[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$Entry18:8726850248java.lang.Class19:26414845248java.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中间件替换队列