线上问题排查套路
- df, free ,top 三连
- jstack, jmap 查jvm
一. CPU 查看
线程总览
可以先用 pstree -p [pid] | wc -l 看看进程内部的线程个数是否合理,
[@js_38_140 platform-new]# pstree -p 30081 | wc -l
104
然后再使用 jstack 查看某个线程
-
top -H -p pid查看线程
-H: 进入线程模式, 显示 CPU 利用率高的线程 -
printf '%x \n' threadId将上一步排位高的线程id, 转换为16进制的 nid -
在 jstack 中找到线程的堆栈信息
jstack pid|grep nid -C5 --color
-C5: 显示上下5行 -
从整体上把握线程状态分布
cat jstack.log | grep 'java.lang.Thread.State' | sort -nr | uniq -c
sort -nr: -n 按照字典序列排序, -r 倒序
uniq -c: 去重后, 显示重合的行数的个数# 全局上把握线程状态 41 java.lang.Thread.State: WAITING (parking) 6 java.lang.Thread.State: WAITING (on object monitor) 8 java.lang.Thread.State: TIMED_WAITING (sleeping) 24 java.lang.Thread.State: TIMED_WAITING (parking) 4 java.lang.Thread.State: TIMED_WAITING (on object monitor) 27 java.lang.Thread.State: RUNNABLE #### 线程状态含义 BLOCKED: 等待监视锁进入或重新进入 Synchronized 代码块 WAITING: 不限时的等待对象锁, 是调用(Object.wait, Thread.join ,LockSupport.park)后进入的状态, 等待另一个线程调用 (Object.notify,Thread.join等待另一个线程执行完毕) TIMED_WAITING: 限时的等待对象锁, 是调用( Thread.sleep Object.wait with timeout Thread.join with timeout LockSupport.parkNanos LockSupport.parkUntil )后进入的状态
查看 gc 是否频繁
jstat -gc pid 1000 : 对 gc 分代情况做观察, 1000ms 观察一次
[@js_38_140 platform-new]# jstat -gc 16520 1000
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
799232.0 778752.0 301309.0 0.0 2566656.0 698677.7 5508096.0 3155978.5 221168.0 203019.0 26416.0 24950.0 64 23.321 10 21.769 45.090
799232.0 778752.0 301309.0 0.0 2566656.0 698684.9 5508096.0 3155978.5 221168.0 203019.0 26416.0 24950.0 64 23.321 10 21.769 45.090
799232.0 778752.0 301309.0 0.0 2566656.0 698713.6 5508096.0 3155978.5 221168.0 203019.0 26416.0 24950.0 64 23.321 10 21.769 45.090
799232.0 778752.0 301309.0 0.0 2566656.0 698728.0 5508096.0 3155978.5 221168.0 203019.0 26416.0 24950.0 64 23.321 10 21.769 45.090
799232.0 778752.0 301309.0 0.0 2566656.0 698738.5 5508096.0 3155978.5 221168.0 203019.0 26416.0 24950.0 64 23.321 10 21.769 45.090
799232.0 778752.0 301309.0 0.0 2566656.0 698748.0 5508096.0 3155978.5 221168.0 203019.0 26416.0 24950.0 64 23.321 10 21.769 45.090
S0C/S1C、S0U/S1U、EC/EU、OC/OU、MC/MU 分别代表两个 Survivor 区、Eden 区、老年代、元数据区的容量和使用量。
YGC/YGT、FGC/FGCT、GCT 则代表 YoungGc、FullGc 的耗时和次数以及总耗时。
如果观察到 gc 频繁, 再对 gc 进一步分析
详细的 column 意思
查看上下文切换是否频繁
- 查看整个操作系统上下文切换 :
vmstat 1(vmstat 汇报 cpu, 内存, 磁盘情况)
# 每隔一秒监视一次
[@js_38_140 platform-new]# vmstat 1
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
1 0 0 16948668 163796 37177828 0 0 1 12 0 0 3 1 96 0 0
0 0 0 16948636 163796 37177864 0 0 0 0 570 1114 0 0 100 0 0
0 0 0 16948636 163796 37177864 0 0 0 0 661 1237 0 0 99 0 0
0 0 0 16948404 163796 37177868 0 0 0 28 662 1243 0 0 100 0 0
0 0 0 16948280 163796 37177868 0 0 0 0 676 1279 0 0 100 0 0
0 0 0 16948280 163796 37177868 0 0 0 68 640 1217 0 0 100 0 0
cs: 上下文切换次数
二. 磁盘查看
首先查看磁盘空间
磁盘空间
[@js_38_140 platform-new]# df -h
文件系统 容量 已用 可用 已用% 挂载点
/dev/vda1 99G 55G 39G 59% /
devtmpfs 32G 0 32G 0% /dev
tmpfs 32G 1.1G 31G 4% /tmp
tmpfs 32G 3.2G 29G 10% /run
tmpfs 32G 0 32G 0% /sys/fs/cgroup
/dev/vdb 800G 559G 242G 70% /search/odin
tmpfs 6.3G 0 6.3G 0% /run/user/0
tmpfs 6.3G 0 6.3G 0% /run/user/995
更多时候需要查看的是磁盘性能问题
磁盘性能问题
-
使用
iostat -d -k -x查看每块磁盘的性能
(-d: display-k: kb/s-x: extend info)[@js_38_140 platform-new]# iostat -d -k -x Linux 3.10.0-327.el7.x86_64 (js_38_140) 2021年06月16日 _x86_64_ (4 CPU) Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util vda 0.00 1.57 0.02 1.48 3.71 17.18 27.82 0.00 3.15 8.10 3.08 0.79 0.12 vdb 0.00 0.00 0.01 0.09 1.84 31.27 647.19 0.00 22.62 6.22 24.01 0.77 0.01%util: 磁盘使用的贷款百分比, 这个数接近 100% ,磁盘读写达到饱和rrqm/s: 每秒读取的数据速度wrqm/s: 每秒写出的数据速度
-
查看哪个进程在进行 I/O
(1) 首先, 使用iotop查看操作系统中进行 I/O 的线程. iotop 中显示的是线程 Id
(2) 然后使用 readlinkreadlink -f /proc/*/task/[线程id]/../..将线程 Id 转换为对应的进程 Id
(3) 找到进程 pid 后, 可以使用cat /proc/[pid]/io或lsof -p [pid]的方式查看进程读写状况# 查看线程 id [@js_38_140 platform-new]# iotop Total DISK READ : 0.00 B/s | Total DISK WRITE : 3.87 K/s Actual DISK READ: 0.00 B/s | Actual DISK WRITE: 19.37 K/s TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND 16016 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.01 % [kworker/2:0] 1582 be/4 root 0.00 B/s 3.87 K/s 0.00 % 0.00 % rsyslogd -n [rs:main Q:Reg] 2048 be/4 zabbix 0.00 B/s 0.00 B/s 0.00 % 0.00 % zabbix_agentd: active checks ~getting list of active checks] # 查看 2048 对应的进程id [@js_38_140 platform-new]# readlink -f /proc/*/task/2048/../.. /proc/2048 # 查看对应的进程文件读写信息 [@js_38_140 platform-new]# cat /proc/2038/io rchar: 34321355392 wchar: 56 syscr: 68909031 syscw: 1 read_bytes: 3989504 write_bytes: 0 cancelled_write_bytes: 0 # 查看打开的文件 [@js_38_140 platform-new]# lsof -p 2048 COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME zabbix_ag 2048 zabbix cwd DIR 253,1 4096 2 / zabbix_ag 2048 zabbix rtd DIR 253,1 4096 2 / zabbix_ag 2048 zabbix txt REG 253,1 1391380 3670082 /opt/zabbix/sbin/zabbix_agentd zabbix_ag 2048 zabbix mem REG 253,1 142304 1311974 /usr/lib64/libpthread-2.17.so zabbix_ag 2048 zabbix mem REG 253,1 37328 1321434 /usr/lib64/libnss_sss.so.2 zabbix_ag 2048 zabbix mem REG 253,1 61928 1311966 /usr/lib64/libnss_files-2.17.so zabbix_ag 2048 zabbix mem REG 253,1 2112384 1311948 /usr/lib64/libc-2.17.so zabbix_ag 2048 zabbix mem REG 253,1 110808 1311976 /usr/lib64/libresolv-2.17.so zabbix_ag 2048 zabbix mem REG 253,1 19520 1311954 /usr/lib64/libdl-2.17.so zabbix_ag 2048 zabbix mem REG 253,1 1141560 1311956 /usr/lib64/libm-2.17.so zabbix_ag 2048 zabbix mem REG 253,1 164440 1327030 /usr/lib64/ld-2.17.so zabbix_ag 2048 zabbix DEL REG 0,4 0 /SYSV6c010046 zabbix_ag 2048 zabbix 0r CHR 1,3 0t0 1028 /dev/null zabbix_ag 2048 zabbix 1w REG 253,1 281987 3678748 /opt/zabbix/logs/zabbix_agentd.log zabbix_ag 2048 zabbix 2w REG 253,1 281987 3678748 /opt/zabbix/logs/zabbix_agentd.log zabbix_ag 2048 zabbix 3w REG 253,1 4 3670079 /opt/zabbix/logs/zabbix_agentd.pid zabbix_ag 2048 zabbix 4u IPv4 21553 0t0 TCP *:zabbix-agent (LISTEN)
三. 内存
内存问题查看起来麻烦一些, 主要包括 OOM, GC, 对外内存. 一般先从 free 查看内存的是使用率入手
1-OOM
OOM 分为几种情况
-
没有足够内存给线程分配 java 栈
变现为, 报错Exception in thread "main" java.lang.OutOfMemoryError: unable to create new native thread解决方法: 可以增大操作系统对线程数量的限制. 修改
nofile和nproc配置[@js_38_140 platform-new]# cat /etc/security/limits.conf | grep -E 'nofile|nproc' # - nofile - max number of open file descriptors # - nproc - max number of processes * soft nofile 65535 * hard nofile 65535 * soft nproc 16384 * hard nproc 32768 -
使用
jmap定位内存泄漏
首先, 可以使用jmap -histo [pid]打印内存中的对象报告直方图@js_38_140 platform-new]# jmap -histo 30081 | head -20 num #instances #bytes class name ---------------------------------------------- 1: 1447808 466908384 [B 2: 4098152 383624664 [C 3: 802414 315746032 [I 4: 12209 136642048 [J 5: 1497895 71414872 [Ljava.lang.Object; 6: 2765753 66378072 scala.collection.immutable.$colon$colon 7: 2712586 65102064 java.lang.String 8: 1290725 30977400 scala.Tuple2 9: 1251112 30026688 java.lang.Long然后, 如果看不出来, 一般使用
jmap -dump:format=b,file=[fileName] [pid]导出 java 进程的 dump 文件, 通过mat工具分析文件
(1) 查看内存泄漏原因, 点击Leak Suspects选项卡即可
(2)Top Consumers选项卡来查看最大对象报告
(3)thread overview进行线程分析
日常开发中，内存泄漏是比较常见的事，并且比较隐蔽，需要开发者更加关注细节。常见原因比如:
(1) 每次请求都 new 对象，导致大量重复创建对象；
(2) 进行文件流操作但未正确关闭；
(3) 手动不当触发 GC；
(4) ByteBuffer 缓存分配不合理等都会造成代码 OOM。
另一方面，可以在启动参数中加入 -XX:+HeapDumpOnOutOfMemoryError 让发生 OOM 时保存 dump 文件。
2-GC日志分析
上面说过, 使用 jstat 分析各代 gc 情况, 但一般都是记录 gc 日志, 观察 gc 日志来排查问题. 启动参数加上 -verbose:gc，-XX:+PrintGCDetails，-XX:+PrintGCDateStamps，-XX:+PrintGCTimeStamps 开启 gc 日志. 一般使用 G1 收集器, 所以加上 -XX:+UseG1GC
1. G1 的 youngGC 日志分析
2826.897: [GC pause (G1 Evacuation Pause) (young), 0.0035277 secs]:
young gc 总共耗时 3.5 ms[Parallel Time: 2.1 ms, GC Workers: 8]:
8个线程进行 gc, 并行收集垃圾导致 stop the world 的耗时 2.1 ms[Ext Root Scanning (ms): Min: 1.1, Avg: 1.2, Max: 1.4, Diff: 0.3, Sum: 9.3]:
进行可达性分析时扫描 root 对象的耗时 (虚拟机栈中引用的对象(方法的局部变量), 元空间的静态属性引用, 本地方法JNI引用对象)[Update RS (ms): Min: 0.4, Avg: 0.5, Max: 0.6, Diff: 0.2, Sum: 4.3]:
更新 remember set 的耗时. remember set 中记录着新生代 region 中指向 old region 对象的映射[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.4]:
扫描 remember set 的时间[Object Copy (ms): Min: 0.1, Avg: 0.2, Max: 0.2, Diff: 0.1, Sum: 1.4]:
在 G1 按照用户指定的停顿时间选择 Cset 中包含的 region 后, 将指定 region 存活对象复制压缩到另一个 region 的时间
这些指标中, 容易出现问题的是 Root Scanning 和 Ref Proc,
前者可能是线程数过多, 导致扫描方法局变量的时间过长; 后者表示处理软引用, 弱引用, 虚引用, final 引用的时间过多. g1 希望少使用软引用, 因为软引用会一直占据内存空间直到空间耗尽时被Full GC回收掉
gc 时间在日志中体现为三种类型, 如下:
[Times: user=11.53 sys=1.38, real=1.03 secs]
- (1) real: 真实的 clock 时间
- (2) user: 用户态下 cpu 耗时
- (3) sys: 内核态下 cpu 耗时
通常发现, user + sys 的时间大于 real, 这是因为现在的 gc 收集器是多线程的, user 和 sys 是统计每个线程加在一起的耗时.如果是 Serial 收集器, 就会得到 user = real. 因为gc线程只有一个
[Times: user=0.09 sys=0.00, real=0.09 secs]
2. G1 的 fullGC
g1 大多数只有 mix gc, 很少会发生 full gc, 只有如下几个情况会产生 full gc, 退化为使用 Serial 收集器
- old 区域已经沾满
在进行 mixed gc 之前, old 区域已经沾满, 则 g1 会跳过并发标记周期. 这种情况下需要增加堆大小或调整周期. 例如增加线程数 -XX:ConcGCThreads 等 - survivor 晋升失败或者疏散失败
G1在进行GC的时候没有足够的内存供存活对象或晋升对象使用，由此触发了Full GC。可以在 gc 日志中看到(to-space exhausted)或者（to-space overflow）。解决这种问题的方式是：
(a) 增加-XX:G1ReservePercent选项的值（并相应增加总的堆大小），为“目标空间”增加预留内存量。
(b) 通过减少-XX:InitiatingHeapOccupancyPercent提前启动标记周期。
© 也可以通过增加-XX:ConcGCThreads选项的值来增加并行标记线程的数目。 - 巨型对象分配失败
当巨型对象找不到合适的空间进行分配时，就会启动 Full GC，来释放空间。这种情况下，应该避免分配大量的巨型对象，增加内存或者增大-XX:G1HeapRegionSize，使巨型对象不再是巨型对象。
有时, 我们需要在一次 fullGC 的前后 dump 日志, 观察 full gc 发生前后的变化.有2中方法开启
- 启动参数加上
-XX:+HeapDumpBeforeFullGC -XX:+HeapDumpAfterFullGC -XX:HeapDumpPath=[file location] - 启动参数只加上
-XX:HeapDumpPath=[file location]一个参数, 然后使用如下两个参数临时开启 full gc dump file
这样在发生一次 full gc 后, 就有了相关日志 (就可以看到是上述哪个原因导致的 full gc, 还是 metaspace 导致的)jinfo -flag +HeapDumpBeforeFullGC [pid] jinfo -flag +HeapDumpAfterFullGC [pid]
四. 堆外内存
堆外内存只有在 fullgc 时才能释放, 所以堆内存溢出的整体思路为:
-
首先开启 nmt, 让 jvm 记录堆外内存消息
需要在启动参数中加入-XX:NativeMemoryTracking=summary或者-XX:NativeMemoryTracking=detail，会有略微性能损耗。 -
使用 jcmd 设置 nmt 信息读取基准点
一般对于堆外内存缓慢增长直到爆炸的情况来说，可以先设一个基线jcmd [pid] VM.native_memory baseline -
手动触发 full gc
jmap -histo:live pid -
再次用 jcmd 查看 nmt 堆外内存是否释放
等放一段时间后再去看看内存增长的情况，通过jcmd [pid] VM.native_memory detail.diff(summary.diff)做一下 summary 或者 detail 级别的 diff。 diff 信息显示如下, 我们只关注 internal 即可
- 如果释放了, 说明堆外内存设置太小, 增大: 通过
-XX:MaxDirectMemorySize进行调整 - 如果没释放, 就要用 mat 分析
DirectByteBuffer对象的引用关系 (dominateTree标签)
六. 关于 MetaSpace
Metaspace使⽤的是本地内存，⽽不是堆内存. 很容易有个误区是Matespace可以随便⽤，不管使⽤多少，只要不超本地内存就不会触发GC，这是错误的。
Matespace 的设置⽅式是: -XX: MetaspaceSize=**M, 让 Matespace 达到该值时触发 Full GC, 如果不设置Matespace, 默认值很⼩，也
就20M左右, 如果程序 Load Class ⽐较多，很容易触发 Full GC。
MetaSpace 导致的 full gc 一方面可能是元空间大小太小; 另一方面可能是在循环中使用了CGLIB动态代理产生了新类, 因为⼀个类是由这个类的类加载器加上全限定名（由包名&类名组成) 确定唯⼀性的, 而动态代理生成的类名是变化的, 导致类加载过多
233
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
