容器下Java应用问题排查步骤

发表于： 分类于：
字数： 4168 阅读：≈ 9分钟 浏览：
总结摘要
容器下Java应用问题排查步骤

1 基本信息收集

  1. 明确应用的JDK 版本，不同JDK版本参数配置有差异。

    1. 尤其是低版本JDK切换到>=JDK1.8中，永久代变为元空间对应的控制参数发生变化。
    1
2
3
4
5

    # JDK1.7及之前版本
-XX:PermSize=128m -XX:MaxPermSize=256m

# JDK1.8及之后版本
-XX:MetaspaceSize=128m -XX:MaxMetaspaceSize=256m

  2. 目前应用的运行状况是什么？

    1. 是内存居高不下，内存缓慢增加还是进程突然宕掉？（或者是应用卡死还是自动重启了？）
    2. 现象发生的节点，近期有无配置变更、有无版本升级、有无应用本身的相关监控数据。

2 保留现场

如果条件允许不建议直接重启或者回滚，可以先保留现场，需要保存如下内容。

2.1 Linux日志

用于分析VM层面的OOM情况。如果观察到应用Docker已经宕掉或者重启，有概率是被linux oom_killer kill掉。

1
2
3
4
5
6
7
8

> dmesg -T|grep -i kill|less 

## 情况一：JVM committed 内存量 < 容器内存上限，并且 JVM committed 内存量 > 操作系统可用内存
[Mon Jun 26 13:44:10 2023] Out of memory: Kill process 26727 (java) score 275 or sacrifice child
 [Mon Jun 26 13:44:10 2023] Killed process 26727 (java), UID 0, total-vm:14137304kB, anon-rss:8854784kB, file-rss:0kB, shmem-rss:0kB

## 情况二：#### JVM committed 内存量 > 容器内存上限，并且 JVM committed 内存量 < 操作系统可用内存
[Sat Jun 17 15:55:34 2023] Memory cgroup out of memory: Killed process 4906 (java) total-vm:4563472kB, anon-rss:119968kB, file-rss:16776kB, shmem-rss:0kB, UID:0 pgtables:1036kB oom_score_adj:0

2.2 当前JVM启动参数 

1
2

# 进入容器内，执行
ps -ef|grep java

2.3 查看内存状态（jstat) 

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35

jps -l 
## 查看指定进程每250ms，共20次的gc收集情况，输出各区域容量，已用空间
jstat -gc <pid> 250 20

S0C：年轻代中第一个survivor（幸存区）的容量 （KB）
S1C：年轻代中第二个survivor（幸存区）的容量 (KB)
S0U：年轻代中第一个survivor（幸存区）目前已使用空间 (KB)
S1U：年轻代中第二个survivor（幸存区）目前已使用空间 (KB)
EC：年轻代中Eden（伊甸园）的容量 (KB)
EU：年轻代中Eden（伊甸园）目前已使用空间 (KB)
OC：Old代的容量 (KB)
OU：Old代目前已使用空间 (KB)
MC：metaspace(元空间)的容量 (KB)
MU：metaspace(元空间)目前已使用空间 (KB)
CCSC：当前压缩类空间的容量 (KB)
CCSU：当前压缩类空间目前已使用空间 (KB)
YGC：从应用程序启动到采样时年轻代中gc次数
YGCT：从应用程序启动到采样时年轻代中gc所用时间(s)
FGC：从应用程序启动到采样时old代(全gc)gc次数
FGCT：从应用程序启动到采样时old代(全gc)gc所用时间(s)

## 关注已使用空间占用总空间的百分比
jstat -gcutil <pid> 250 20

S0：年轻代中第一个survivor（幸存区）已使用的占当前容量百分比
S1：年轻代中第二个survivor（幸存区）已使用的占当前容量百分比
E：年轻代中Eden（伊甸园）已使用的占当前容量百分比
O：old代已使用的占当前容量百分比
M：元数据区已使用的占当前容量百分比
CCS：压缩类空间已使用的占当前容量百分比
YGC ：从应用程序启动到采样时年轻代中gc次数
YGCT ：从应用程序启动到采样时年轻代中gc所用时间(s)
FGC ：从应用程序启动到采样时old代(全gc)gc次数
FGCT ：从应用程序启动到采样时old代(全gc)gc所用时间(s)
GCT：从应用程序启动到采样时gc用的总时间(s)

2.4 查看内存状态(arthas) 

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55

# 启动命令
> java -jar arthas-boot.jar
> 选择1

# 查看jvm参数
> jvm
和Thread有关的参数

COUNT: JVM当前活跃的线程数
DAEMON-COUNT: JVM当前活跃的守护线程数
PEAK-COUNT: 从JVM启动开始曾经活着的最大线程数
STARTED-COUNT: 从JVM启动开始总共启动过的线程次数
DEADLOCK-COUNT: JVM当前死锁的线程数


# 查看jvm情况
> memory 或者 dashboard

> thread -n 3 # 查看最繁忙的三个线程栈信息
> thread # 以直观的方式展现所有的线程情况
> thread --state 线程状态 # 查看指定状态线程
> thread -b #找出当前阻塞其他线程的线程
> thread <id> #查看指定id的线程
> jad org.springframework.web.servlet.DispatcherServlet # 直接反编译出java 源代码，包含一此额外信息的

> watch com.test.ob testMethod "{params, returnObj, throwExp}" -e -x 2 # 同时监控入参，返回值，及异常(可以去掉throwExp和-e，防止结果没有输出)
> watch com.test.ob testMethod -x 2
> thread -all # 显示所有线程
# 监控指定类指定方法的耗时
>trace com.hd123.latin.sys.dao.jobdataprocess.JobDataProcessDaoImpl listExecuteRecords

# 直接统计 primeFactors 的响应问题
> monitor -c 5 demo.MathGame primeFactors

# 查看加载类信息

> classloader # 默认按类加载器类型查看统计信息
> classloader -l # 按类加载器的实例查看统计信息，可以看到加载类的hascode
> classloader -t # 可以看到继承树
> classloader -c 680f2737 # 通过类加载器的hash，查看此类加载器实际所在的位置

# 内存定位
>  profiler start -e alloc # 生成内存分区的火焰图
>  profiler getSamples #获取已采集的sample数量
>  profiler stop --format html --file /java/output.html #停止采集，并生成html，后面是文件存放的地址

# 导出堆dump
> heapdump /java/heapdump.hprof

# 查看CPU耗时
> profiler start #启动采集
> profiler stop #停止采集

# 退出arthas
> exit

2.5 查看内存状态(jcmd)

  • 调整jvm参数开启特性，加入参数 ：-XX:NativeMemoryTracking=summary 或者 -XX:NativeMemoryTracking=detail(NMT必须先通过VM启动参数中打开，不过要注意的是，打开NMT会带来5%-10%的性能损耗)
  • 快速检查内存使用summary;排查native 内存泄露使用detail，生产环境建议使用summary。
  • 查看内存报告命令
1
2
3
4
5
6

# 查看进程 PID
ps aux | grep java

# 查看内存报告
jcmd <PID> VM.native_memory summary
jcmd <PID> VM.native_memory detail
  • 报告解读
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51

-XX:+UnlockDiagnosticVMOptions -XX:+PrintNMTStatistics

## 报告介绍
reserved表示应用可用的内存大小，
committed表示应用正在使用的内存大小

Total: reserved=1927465KB +66KB, committed=887589KB +66KB

-                 Java Heap (reserved=1048576KB, committed=524288KB)
                            (mmap: reserved=1048576KB, committed=524288KB)
 
-                     Class (reserved=387186KB, committed=89842KB)
                            (classes #15588) 已经加载的classes个数
                            (malloc=2162KB #23499)
                            (mmap: reserved=385024KB, committed=87680KB)
               
-                    Thread (reserved=46014KB, committed=46014KB)   
                            (thread #85)   Thread部分表示线程个数
                            (stack: reserved=45648KB, committed=45648KB)
                            (malloc=267KB #448)
                            (arena=98KB #165)
 
-                      Code (reserved=256433KB, committed=39725KB)  表示JIT生成的或者缓存的instructions占用
                            (malloc=6833KB #9122)
                            (mmap: reserved=249600KB, committed=32892KB)
 
-                        GC (reserved=49673KB, committed=48137KB)  目前已经占用的内存空间用于帮助GC
                            (malloc=46593KB #362)
                            (mmap: reserved=3080KB, committed=1544KB)
 
-                  Compiler (reserved=309KB, committed=309KB)
                            (malloc=178KB #1157)
                            (arena=131KB #6)
 
-                  Internal (reserved=71623KB +1KB, committed=71623KB +1KB) 表示命令行解析、JVMTI等占用
                            (malloc=71591KB +1KB #19791 +4)
                            (mmap: reserved=32KB, committed=32KB)
 
-                    Symbol (reserved=22144KB, committed=22144KB)  表示诸如string table及constant pool等symbol占用
                            (malloc=18492KB #182273)
                            (arena=3652KB #1)
 
-    Native Memory Tracking (reserved=4222KB +66KB, committed=4222KB +66KB)  表示该功能自身占用
                            (malloc=425KB +54KB #6037 +760)
                            (tracking overhead=3797KB +12KB)
 
-               Arena Chunk (reserved=189KB, committed=189KB) 表示arena chunk占用
                            (malloc=189KB)
 
-                   Unknown (reserved=41096KB, committed=41096KB)
                            (mmap: reserved=41096KB, committed=41096KB)

2.6 导堆（heapdump 文件）

注意，如果应用运行正常，此操作会导致应用短时间卡死，请慎重操作。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17

# 进入容器内执行（前提是容器镜像提供了相关命令工具）
# 查看容器内进程id
jps -l
# 或者
top

#jmap命令保存整个Java堆（在你dump的时间不是事故发生点的时候尤其推荐）
jmap -dump:format=b,file=heap.hprof <pid> 

#jmap命令只保存Java堆中的存活对象, 包含live选项，会在堆转储前执行一次Full GC
jmap -dump:live,format=b,file=heap.hprof <pid>

#jcmd命令保存整个Java堆,Jdk1.7后有效
jcmd <pid> GC.heap_dump filename=heap.hprof

#在出现OutOfMemoryError的时候JVM自动生成（推荐）节点剩余内存不足heapdump会生成失败
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/heap.bin

2.7 建议设置GC日志打印 

1
2
3
4
5

# Java8及以下
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:<path>

# Java9及以上
-Xlog:gc*:<path>:time

2.8 建议设置输出错误日志 

1
2

# JDK5及以上
-XX:ErrorFile=/path/to/logs/hs_err_pid%p.log

2.9 内存栈 

1
2
3
4
5
6

# 进入容器内执行（前提是容器镜像提供了相关命令工具）
#jstack生成，推荐
jstack <pid> > jstack.log

# Java8及以上，jcmd生成
jcmd <pid> Thread.print > jstack.log

2.10 查看未关闭的文件句柄 

1

lsof -a -p <pid>|wc -l

2.11 Java 日志

如果是JVM内存溢出，一般是会打出相关日志。如果日志较为明确，可以帮助我们快速定位问题。比如：

  1. 元空间溢出：java.lang.OutOfMemoryError: Metaspace
  2. 直接内存溢出netty会报OutOfDirectMemoryError: failed to allocate capacity byte(s) of direct memory (used: usedMemory , max: DIRECT_MEMORY_LIMIT )。
1
2
3
4
5
6
7
8

#<日志文件> 替换为 实际日志地址
grep "java.lang.OutOfMemoryError" <日志文件>

#如果日志文件是压缩文件（如.log.gz），你可以使用zgrep命令
zgrep "java.lang.OutOfMemoryError" /path/to/your/logfile.gz

#如果是多个文件的话在日志地址上增加通配符
grep "java.lang.OutOfMemoryError" /path/to/your/logs/*.log

较为常见的是堆内存溢出：java.lang.OutOfMemoryError: Java heap space

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11

## JVM生成的错误日志文件：如果使用了-XX:ErrorFile参数指定了错误日志文件的路径，那么JVM崩溃时会生成一个专门的错误日志文件，其中包含了崩溃时的详细信息。
hs_err_pid6.log

## SpringBoot 应用一般在xx-service-info.log中输出，例如
2024-08-29 16:25:57,639 [http-nio-8080-exec-8] [5190a8f9aa4b4a77a44e575c8dce2c6d] ERROR net.sf.jasperreports.engine.fill.JRFillSubreport - Fill 1: exception
java.lang.OutOfMemoryError: Java heap space
2024-08-29 16:29:54,258 [http-nio-8080-exec-8] [5190a8f9aa4b4a77a44e575c8dce2c6d] INFO  com.demo.web.config.ApiTraceLogConfig - {"client":"172.16.3.92","method":"POST","uri":"/gem-service/api/printservice/v1/execute","headers":{"authorization":["Basic Z3Vlc3Q6Z3Vlc3Q="],"transfer-encoding":["chunked"],"host":["172.16.3.93:18086"],"content-type":["application/json"]},"body":{"templateFileId":"printTemplate/report64e3799c21914f3196b05c2324f9ebae/销售清单wy.jasper","dataSourceId":"2cd680836e36d397016e36f5cbe9314b"

## SpringMVC Tomcat 应用一般在
catalina.<date>.log：这是Tomcat的日志文件，按照日期进行命名。例如，catalina.2024-09-06.log
localhost.<date>.log：这个文件记录了本地主机相关的日志信息，虽然通常不包含JVM的错误信息，但在某些情况下也可能记录相关信息

2.12 查看请求来源

无相关调用方日志辅助定位时，通过tcpdump定位请求来源 Tcpdump 详解（抓包）_tcpdump抓包命令-CSDN博客 

1
2
3
4
5
6
7
8

# 监听目标主机的端口
tcpdump -vnn dst port 8080

# 监听目标IP和端口（如果是docker，目标使用对应docker的ip)
tcpdump -i <网卡名，比如docker0> -vnn dst port <端口号，比如8080> and dst host <目标IP，比如172.86.0.5>

	# 保存到快照，抓满100个退出（使用wireshark客户端查看pcap文件）
tcpdump -i <网卡名，比如docker0> -vnn dst port <端口号，比如8080> and dst host <目标IP，比如172.86.0.5> -w ./result.pcap -c 100