首页 > 编程入门 文章详情

JVM问题排查手册+案例分析

编程入门 行业动态 更新时间:2024-10-26 22:23:06

JVM问题排查手册+<a href=https://www.elefans.com/category/jswz/34/1768167.html style=案例分析"/>

JVM问题排查手册+案例分析

JVM内存层面

1 jstack

当前jvm 1 线程数统计：
jstack 1 |grep ‘tid’| wc -l (linux 64位系统中jvm线程默认栈大小为1MB)

查看进程 1 中线程状态统计
jstack 1 | grep java.lang.Thread.State | awk ‘{print $2}’ | sort | uniq -c

或者
jstack 1 > stack.txt (方便分析)
cat stack.txt | grep ‘tid’| wc -l
cat stack.txt | grep java.lang.Thread.State | awk ‘{print $2}’ | sort | uniq -c

2 查看堆内存使用情况：

JDK9之前：
jmap -heap 1

若报错：
解决：
.8.0-openjdk-debuginfo-1.8.0.212.b04-0.el7_6.x86_64.rpm

JDK9及之后：
jhsdb jmap --heap --pid 1

Attaching to process ID 6, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.275-b01using thread-local object allocation.
Garbage-First (G1) GC with 4 thread(s)Heap Configuration:MinHeapFreeRatio         = 40MaxHeapFreeRatio         = 70MaxHeapSize              = 10737418240 (10240.0MB)NewSize                  = 1363144 (1.2999954223632812MB)MaxNewSize               = 6442450944 (6144.0MB)OldSize                  = 5452592 (5.1999969482421875MB)NewRatio                 = 2SurvivorRatio            = 8MetaspaceSize            = 21807104 (20.796875MB)CompressedClassSpaceSize = 1073741824 (1024.0MB)MaxMetaspaceSize         = 17592186044415 MBG1HeapRegionSize         = 4194304 (4.0MB)Heap Usage:
G1 Heap:regions  = 2560capacity = 10737418240 (10240.0MB)used     = 3169781704 (3022.9393997192383MB)free     = 7567636536 (7217.060600280762MB)29.520892575383186% used
G1 Young Generation:
Eden Space:regions  = 326capacity = 1673527296 (1596.0MB)used     = 1367343104 (1304.0MB)free     = 306184192 (292.0MB)81.70426065162907% used
Survivor Space:regions  = 10capacity = 41943040 (40.0MB)used     = 41943040 (40.0MB)free     = 0 (0.0MB)100.0% used
G1 Old Generation:regions  = 421capacity = 9021947904 (8604.0MB)used     = 1760495560 (1678.9393997192383MB)free     = 7261452344 (6925.060600280762MB)19.51347512458436% used37539 interned Strings occupying 4198488 bytes.

jmap -histo 1| head -n 30

num     #instances         #bytes  class name
----------------------------------------------1:        125288      249331056  [I2:       2098460      189485944  [C3:       2114036      118386016  ioty.channel.DefaultChannelHandlerContext4:       1753471      112222144  ioty.util.concurrent.ScheduledFutureTask5:       1170371      104111080  [B6:       2088114       50114736  scala.collection.immutable.$colon$colon7:        853367       47788552  java.util.LinkedHashMap8:       1466274       46920768  java.util.HashMap$Node9:        505548       42303832  [Ljava.lang.Object;10:       1746269       41910456  java.lang.String11:        972328       38893120  java.util.LinkedHashMap$Entry12:       1493939       35854536  akka.actor.typed.javadsl.BehaviorBuilder$Case13:       2197653       35162448  java.lang.Object14:        305650       34232800  sun.nio.ch.SocketChannelImpl15:        305641       34231792  ioty.channel.socket.nio.NioSocketChannel16:        298426       33423712  ioty.handler.timeout.IdleStateHandler17:       2042323       32677168  java.lang.Integer18:       1281985       30767640  java.lang.Long...11400:             1             16  sun.util.resources.LocaleData11401:             1             16  sun.util.resources.LocaleData$LocaleDataResourceBundleControlTotal      46489871     2077650456

jmap -dump:live,format=b,file=heap.hprof 1

jmap -dump:format=b,file=heap001.hprof 1

gc日志输出到文件
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:gc.log内存溢出时，堆栈信息输出到文件
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/heap.hprof

3 垃圾收集统计摘要:

jstat -gcutil/-gc pid interval times

jstat -gc 1 1000 20

 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   0.0   40960.0  0.0   40960.0 2654208.0 1150976.0 7790592.0  1810706.4  162632.0 147626.9 20604.0 18679.9    899  154.461   1      2.726  157.1870.0   40960.0  0.0   40960.0 2654208.0 1220608.0 7790592.0  1810706.4  162632.0 147626.9 20604.0 18679.9    899  154.461   1      2.726  157.187

查看gc发生的详细原因：
jstat -gccause pid interval times

4 堆外内存 jcmd

因为通常的垃圾收集日志等记录，并不包含 Direct Buffer 等信息，所以 Direct Buffer 内存诊断也是个比较头疼的事情。
pmap并不知道这部分区域是干什么用的，而只有JVM自己知道，所以, NMT的输出可以看出该内存区域的用处。
在 JDK 8 之后的版本，使用 Native Memory Tracking （ NMT ）特性来进行诊断，你可以在程序启动时加上下面参数：
-XX:NativeMemoryTracking={off|summary|detail}
off: 默认关闭
summary: 只统计各个分类的内存使用情况.
detail: Collect memory usage by individual call sites.

// 打印 NMT 信息
jcmd VM.native_memory detail

// 进行 baseline，以对比分配内存变化
jcmd VM.native_memory baseline

// 进行 diff，对比分配内存变化
jcmd VM.native_memory detail.diff

//关闭
jcmd VM.native_memory shutdown

jcmd 1 VM.native_memory summary

1:Native Memory Tracking:Total: reserved=13100313KB, committed=11882441KB
-                 Java Heap (reserved=10485760KB, committed=10485760KB)(mmap: reserved=10485760KB, committed=10485760KB) -                     Class (reserved=1196260KB, committed=166956KB)(classes #25274)(malloc=4324KB #56053) (mmap: reserved=1191936KB, committed=162632KB) -                    Thread (reserved=131067KB, committed=131067KB)(thread #128)(stack: reserved=130488KB, committed=130488KB)(malloc=429KB #756) (arena=150KB #252)-                      Code (reserved=265293KB, committed=97205KB)(malloc=15693KB #25720) (mmap: reserved=249600KB, committed=81512KB) -                        GC (reserved=498524KB, committed=498524KB)(malloc=76636KB #251626) (mmap: reserved=421888KB, committed=421888KB) -                  Compiler (reserved=587KB, committed=587KB)(malloc=456KB #3075) (arena=131KB #6)-                  Internal (reserved=453142KB, committed=453142KB)(malloc=453110KB #244674) (mmap: reserved=32KB, committed=32KB) -                    Symbol (reserved=34767KB, committed=34767KB)(malloc=31978KB #288870) (arena=2789KB #1)-    Native Memory Tracking (reserved=14239KB, committed=14239KB)(malloc=513KB #7314) (tracking overhead=13726KB)-               Arena Chunk (reserved=194KB, committed=194KB)(malloc=194KB) -                   Unknown (reserved=20480KB, committed=0KB)(mmap: reserved=20480KB, committed=0KB)

5 类加载信息相关

jstat -class 1

至于JVM默认启动参数，可以通过命令
java -XX:+PrintCommandLineFlags -version

查看运行时所有参数：
java -XX:+PrintFlagsFinal -version

查看运行中java设置的所有修改的参数：
jinfo -flags 1

查看运行中的java实例某个参数：
jinfo -flag InitialHeapSize 1
jinfo -flag MaxHeapSize 1
jinfo -flag UseCompressedOops 1
jinfo -flag NativeMemoryTracking 1
jinfo -flag UseG1GC 1

查看Eden 和 两个 Survivor 区域比例：
jinfo -flag SurvivorRatio 1

查看新生代 ( Young ) 与老年代 ( Old ) 的比例:
jinfo -flag NewRatio 1

系统层面内存分析策略：

1 查看系统内存概况 top/free

2 查看进程的内存概况 pmap

  1. pmap -x 1

  2. 每隔两秒钟打印总的内存占用量：
    while true; do pmap -x 28056 | tail -1; sleep 2; done

1:   java -Xms10240m -Xmx10240m -XX:+UseG1GC -XX:NativeMemoryTracking=detail -javaagent:/data/agent/skywalking-agent.jar -jar -Dspring.profiles.active=prod /data/admin.jarAddress Perm   Offset Device     Inode     Size     Rss     Pss Referenced Anonymous Swap Locked Mapping540000000 rw-p 00000000  00:00         0 10506364 7500416 7500416    7500416   7500416    0      0 7c141f000 ---p 00000000  00:00         0  1027972       0       0          0         0    0      0 5616124f1000 r-xp 00000000  fd:10 540604495        4       4       2          4         0    0      0 java5616126f1000 r--p 00000000  fd:10 540604495        4       4       4          4         4    0      0 java5616126f2000 rw-p 00001000  fd:10 540604495        4       4       4          4         4    0      0 java5616138ed000 rw-p 00000000  00:00         0      132      32      32         32        32    0      0 [heap]7efba8000000 rw-p 00000000  00:00         0      132      28      28         28        28    0      0 ....7eff2abff000 rw-p 0001d000  fd:10 806800350        4       4       4          4         4    0      0 libpthread-2.31.so7eff2ac00000 rw-p 00000000  00:00         0       16       4       4          4         4    0      0 7eff2ac04000 r--s 00004000  fd:10   8100599        8       8       4          8         0    0      0 apm-activemq-5.x-plugin-8.1.0.jar7eff2ac06000 rw-p 00000000  00:00         0       12      12      12         12        12    0      0 7eff2ac2d000 r--p 00024000  fd:10 806800234       32      20       4         20         0    0      0 ld-2.31.so7eff2ac35000 r--p 00000000  00:00         0        4       0       0          0         0    0      0 7ffee0a0a000 rw-p 00000000  00:00         0      160      68      68         68        68    0      0 [stack]7ffee0ba6000 r-xp 00000000  00:00         0        8       4       0          4         0    0      0 [vdso]
ffffffffff600000 r-xp 00000000  00:00         0        4       0       0          0         0    0      0 [vsyscall]======== ======= ======= ========== ========= ==== ====== 26203424 8814020 8805569    8814020   8797476    0      0 KB

3 列举出正在使用的文件 lsof

  1. 列出所有tcp 网络连接信息: lsof -i tcp | wc -l (数量)
  2. 显示某个进程号下打开的文件量: lsof -p processId. 例如： lsof -p 1
  3. /proc/sys/fs/file-nr，可以看到整个系统目前使用的文件句柄数量

SOCKET句柄泄露带来的内存灾难
.html

案例

案例1 - socket句柄内存泄漏

前段时间，IM服务器（集群3台， 单台10G/8核）频繁重启，大概一天一次，后经分析是socket句柄泛滥，未及时关闭，导致出现大量内存泄露问题，排查过程如下：

  1. 加配置：-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/heap.hprof， 让内存溢出时，堆栈信息输出到文件，然后静静观察，
    （1）ps aux 看下java进程，发现RSS在六七个小时内就上升到了将近8G，而且一直在持续增长，占用带宽20MiBps左右;
    （2）jamp -heap 看下，jvm heap占用不足5G;
    （4）并且下次重启之后，并未发现文件生成，确定是 因为超过了容器最大内存限制，被容器直接杀死（服务部署在K8s管理的Docker容器内）;后来自己在，服务器上通过 jmap -dump,format=b,file=heap.hprof 1，dump 出内存后，使用MAT工具分析后，也没问题。
    （5）jstat -gcutil 发现，youngGC 30秒一次，有点频繁，但还算正常，但未发生fullGC，就很奇怪了。于是，调整 -XX:NewRatio=1 -XX:CMSInitiatingOccupancyFraction=60, 观察后仍然没有fullGC, 直接死掉。

    初步结论：因为IM服务器是基于netty作为基础框架，初步判断是堆外内存泄漏。

  2. 加配置：-XX:NativeMemoryTracking=detail， 使用NMT特性来进行诊断，发现并无异常。

  3. 使用pmap查看内存概况，并且每隔两秒钟打印总的内存占用量： while true; do pmap -x 1 | tail -1; sleep 2; done
    确实一直在增长。

  4. 因初步找不到原因，想着无法fullGC，于是，更换G1垃圾收集器（基于区块Region模型，而不是分代模型），让其尽可能回收老年代对象，于是配置：-XX:+UseG1GC -XX:NewRatio=1。经观察竟然稳住了，维持了9.5G那样子，好像泄漏和回收达到了平衡，不知啥原因平衡了。

  5. 继续排查原因：想起来前段时间，加了TCP连接统计功能，与是查看每台服务器连接数信息，15万连接，发现不对啊，正常4万左右吧（公司日活人数70多万，总注册用户量1亿多），怀疑是不是统计出现问题，于是服务器查看实际创建连接数量： lsof -i tcp -p 1| wc -l， 发现和统计数量一致。确定是socket句柄泄漏导致（Socket内部默认的收发缓冲区大小大概是8K）。

  6. 改代码：排查服务器代码。先说下服务器业务ChannelHandler结构，第一个是ConnectStatisticHandler用于统计TCP连接量，接着是AuthHandler用于认证，如果连接认证通过删除AuthHandler，然后添加ImHandler用于实际业务处理，使用netty自带的IdleStateHandler自定义TCP超时处理，检测超时事件（IdleStateEvent）的回调函数（userEventTriggered）放在了ImHandler里面。
    问题就出在这里！！！
    理论上应该是，每一个App代表一个用户，以客户端的身份和服务器通信，每拿到一个客户端都要去认证，认证通过则进行正常业务，未通过则服务器关闭连接。
    经测试（预发布环境），一个App竟然可以维持几十甚至上百条连接（Channel若中断App会重试）。
    分析发现，客户端在重试期间，存在大量只注册，但未认证的连接，导致出现大量无效连接（这些连接靠TCP keepalive机制探活，TCP keepalive2小时超时断开，这也解释了泄漏和回收达到了平衡的原因），
    解决：因检测超时事件（IdleStateEvent）的回调函数（userEventTriggered）放在了ImHandler里面，此时只注册但未认证的连接还未注册ImHandler，自定义超时检查机制不起作用。所以，将测超时事件的回调函数移到ConnectStatisticHandler里面，问题解决。

  7. 修改代码后发布，连接数4万多，内存维持在8G多，回归正常。

案例2 - cpu被打满

docker环境检查占用cpu飙升的异常java服务

  1. docker status 命令查看服务资源占用情况 获取cpu异常的容器id 60a01eab867b
  2. docker exec -it 60a01eab867b /bin/bash 命令进入容器
  3. top 命令查看该容器线程占用最高的进程PID 1
  4. ps -mp 1 -o THREAD,tid,time 命令获取到1这个进程下面所有线程，通过查看%CPU找到最耗费CPU的线程TID 112（或者使用命令 top -Hp 1）
  5. printf ‘%x’ 112 命令转换成对应的16进制PID 70(112为上一步中获取到的线程TID )
  6. jstack 1 | grep 70 -A 30 命令查看异常信息 注意：1是一开始获取的进程PID,而70则是这个进程下面最耗费CPU的线程TID
  7. jstack 1>stack.txt 命令，将该消耗进程的线程相关信息导出到stack.text文件中，打开这个文件查看每个线程的具体状态然后分析代码异常

案例3 - JVM血坑命令

jmap -histo:live id 会触发full gc，要命！！！

线上配置

Command line: -Xms10240m -Xmx10240m -XX:+UseG1GC -XX:NewRatio=1
-javaagent:/data/agent/skywalking-agent.jar -Dspring.profiles.active=prod -Duser.timezone=Asia/Shanghai

题外篇：

Ubuntu

.html

替换软件源：

mv sources.list sources.list_bak
echo “deb / bionic main restricted universe multiverse” > sources.list
sudo apt-get update
sudo apt-get upgrade

安装网络工具包：
apt install net-tools

更多推荐

JVM问题排查手册+案例分析

本文发布于:2024-02-11 07:52:27，感谢您对本站的认可！
本文链接:https://www.elefans.com/category/jswz/34/1679909.html
版权声明:本站内容均来自互联网，仅供演示用，请勿用于商业和其他非法用途。如果侵犯了您的权益请与我们联系，我们将在24小时内删除。
本文标签：案例分析   手册   JVM

发布评论

评论列表 （有 0 条评论）

最近发表

草根站长

>www.elefans.com

编程频道|电子爱好者 - 技术资讯及电子产品介绍！

热门文章

标签列表