java生产问题排查痕迹 jvm问题排查案例

转载

mob64ca1414c613 2024-07-03 21:27:14

文章标签 java生产问题排查痕迹 java sed ci 文章分类 Java 后端开发

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

若报错：
解决：
http://debuginfo.centos.org/7/x86_64/java-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-b01

using thread-local object allocation.
Garbage-First (G1) GC with 4 thread(s)

Heap Configuration:
   MinHeapFreeRatio         = 40
   MaxHeapFreeRatio         = 70
   MaxHeapSize              = 10737418240 (10240.0MB)
   NewSize                  = 1363144 (1.2999954223632812MB)
   MaxNewSize               = 6442450944 (6144.0MB)
   OldSize                  = 5452592 (5.1999969482421875MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 4194304 (4.0MB)

Heap Usage:
G1 Heap:
   regions  = 2560
   capacity = 10737418240 (10240.0MB)
   used     = 3169781704 (3022.9393997192383MB)
   free     = 7567636536 (7217.060600280762MB)
   29.520892575383186% used
G1 Young Generation:
Eden Space:
   regions  = 326
   capacity = 1673527296 (1596.0MB)
   used     = 1367343104 (1304.0MB)
   free     = 306184192 (292.0MB)
   81.70426065162907% used
Survivor Space:
   regions  = 10
   capacity = 41943040 (40.0MB)
   used     = 41943040 (40.0MB)
   free     = 0 (0.0MB)
   100.0% used
G1 Old Generation:
   regions  = 421
   capacity = 9021947904 (8604.0MB)
   used     = 1760495560 (1678.9393997192383MB)
   free     = 7261452344 (6925.060600280762MB)
   19.51347512458436% used

37539 interned Strings occupying 4198488 bytes.

jmap -histo 1| head -n 30

num     #instances         #bytes  class name
----------------------------------------------
   1:        125288      249331056  [I
   2:       2098460      189485944  [C
   3:       2114036      118386016  io.netty.channel.DefaultChannelHandlerContext
   4:       1753471      112222144  io.netty.util.concurrent.ScheduledFutureTask
   5:       1170371      104111080  [B
   6:       2088114       50114736  scala.collection.immutable.$colon$colon
   7:        853367       47788552  java.util.LinkedHashMap
   8:       1466274       46920768  java.util.HashMap$Node
   9:        505548       42303832  [Ljava.lang.Object;
  10:       1746269       41910456  java.lang.String
  11:        972328       38893120  java.util.LinkedHashMap$Entry
  12:       1493939       35854536  akka.actor.typed.javadsl.BehaviorBuilder$Case
  13:       2197653       35162448  java.lang.Object
  14:        305650       34232800  sun.nio.ch.SocketChannelImpl
  15:        305641       34231792  io.netty.channel.socket.nio.NioSocketChannel
  16:        298426       33423712  io.netty.handler.timeout.IdleStateHandler
  17:       2042323       32677168  java.lang.Integer
  18:       1281985       30767640  java.lang.Long
  ...
  11400:             1             16  sun.util.resources.LocaleData
  11401:             1             16  sun.util.resources.LocaleData$LocaleDataResourceBundleControl
  Total      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.187
 0.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

pmap -x 1
每隔两秒钟打印总的内存占用量：
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.jar
         Address Perm   Offset Device     Inode     Size     Rss     Pss Referenced Anonymous Swap Locked Mapping
       540000000 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 java
    5616126f1000 r--p 00000000  fd:10 540604495        4       4       4          4         4    0      0 java
    5616126f2000 rw-p 00001000  fd:10 540604495        4       4       4          4         4    0      0 java
    5616138ed000 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.so
    7eff2ac00000 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.jar
    7eff2ac06000 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.so
    7eff2ac35000 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

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

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

案例

案例1 - socket句柄内存泄漏

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

加配置：-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作为基础框架，初步判断是堆外内存泄漏。

加配置：-XX:NativeMemoryTracking=detail，使用NMT特性来进行诊断，发现并无异常。
使用pmap查看内存概况，并且每隔两秒钟打印总的内存占用量： while true; do pmap -x 1 | tail -1; sleep 2; done
确实一直在增长。
因初步找不到原因，想着无法fullGC，于是，更换G1垃圾收集器（基于区块Region模型，而不是分代模型），让其尽可能回收老年代对象，于是配置：-XX:+UseG1GC -XX:NewRatio=1。经观察竟然稳住了，维持了9.5G那样子，好像泄漏和回收达到了平衡，不知啥原因平衡了。
继续排查原因：想起来前段时间，加了TCP连接统计功能，与是查看每台服务器连接数信息，15万连接，发现不对啊，正常4万左右吧（公司日活人数70多万，总注册用户量1亿多），怀疑是不是统计出现问题，于是服务器查看实际创建连接数量： lsof -i tcp -p 1| wc -l，发现和统计数量一致。确定是socket句柄泄漏导致（Socket内部默认的收发缓冲区大小大概是8K）。
改代码：排查服务器代码。先说下服务器业务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里面，问题解决。
修改代码后发布，连接数4万多，内存维持在8G多，回归正常。

案例2 - cpu被打满

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

docker status 命令查看服务资源占用情况获取cpu异常的容器id 60a01eab867b
docker exec -it 60a01eab867b /bin/bash 命令进入容器
top 命令查看该容器线程占用最高的进程PID 1
ps -mp 1 -o THREAD,tid,time 命令获取到1这个进程下面所有线程，通过查看%CPU找到最耗费CPU的线程TID 112（或者使用命令 top -Hp 1）
printf ‘%x’ 112 命令转换成对应的16进制PID 70(112为上一步中获取到的线程TID )
jstack 1 | grep 70 -A 30 命令查看异常信息注意：1是一开始获取的进程PID,而70则是这个进程下面最耗费CPU的线程TID
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

替换软件源：

mv sources.list sources.list_bak
 echo “deb http://mirrors.aliyun.com/ubuntu/ bionic main restricted universe multiverse” > sources.list
 sudo apt-get update
 sudo apt-get upgrade安装网络工具包：
 apt install net-tools

本文章为转载内容，我们尊重原作者对文章享有的著作权。如有内容错误或侵权问题，欢迎原作者联系我们进行内容更正或删除文章。

上一篇：java创建线程异步执行 java异步线程实现方式

下一篇：kafka同步数据需要连接数据库吗 kafka数据同步机制

提问和评论都可以，用心的回复会被更多人看到评论

发布评论

相关文章

官方博客	全部文章	热门标签	班级博客
了解我们	网站地图	意见反馈

鸿蒙开发者社区	51CTO学堂
51CTO	软考资讯