ARTICLE DETAIL

资讯详情

深耕网站建设与运营推广的一线实战洞察。

JVM排查实战:从jps到Arthas的6+1工具链使用指南

JVM排查实战:从jps到Arthas的6+1工具链使用指南 很多人第一次接触 JVM 排查时第一个困惑往往是工具这么多到底该先用哪个甚至是“我好像只知道 jstack”。前阵子一个朋友在生产环境遇到 CPU 飙高盯着监控截图却连当前哪个 Java 进程在搞事都没确认就准备去翻代码。这种场景我太熟了因为我自己刚接触 JVM 调优那会儿也是这样JDK 自带工具认不全遇到问题第一反应是重启大法。后来在一连串线上 OOM、Full GC 和死锁事故里把 jps、jstat、jmap、jstack、JConsole、VisualVM 一个个试过来才慢慢形成了自己的排查路径。今天就把这套经验写成文字聊聊我平时怎么用这 6 个工具去分析定位 JVM 问题最后再加餐一个比它们都“下得去手”的 Arthas。1. 一次线上事故让我把工具按使用顺序排好了队1.1 事故现场还原告警响了但不知道从哪下手那是一个周三的傍晚线上支付回调服务突然告警。监控面板上 CPU 使用率一路冲到 90% 以上接口耗时从 50ms 涨到 3 秒几分钟后部分节点开始拒绝新请求。群里第一反应是“是不是又有扫段请求打过来了”但流量看下来并没有明显增长。于是一堆人开始猜死循环频繁 Full GC连接池满了说实话当时大家手里有工具但用得很乱。有人直接上去jstack抓了一把线程栈却不知道看哪一段有人建议马上重启节点恢复但明显没有想清楚根因。折腾了大概半小时才定位到一个ConcurrentHashMap扩容逻辑在高并发下出现热点竞争导致线程大量阻塞在resize()上。事后复盘时我意识到问题本身不复杂但我们缺少一套“按顺序来”的排查思路。1.2 按“进程 → GC → 线程 → 堆 → 可视化 → 在线增强”排队那次之后我把常用工具分了层强制自己按照固定顺序排查不要一上来就抓线程或 dump 堆先用jps确认当前机器上有哪些 Java 进程锁住目标 pid再用jstat看 GC 情况和类加载数据判断是不是 GC 瓶颈用jstack抓线程快照结合top -Hp定位到具体线程用jmap看堆内存分布必要时导出堆快照做离线分析用 JConsole 和 VisualVM 看趋势图尤其是需要长时间观察时最后如果到方法级别还没头绪就上 Arthas 做在线方法级诊断。这套顺序的核心逻辑是先确认“进程活着没有”再看“内存和 GC 是否正常”然后看“线程卡在哪”最后才深入“代码逻辑”。一层层缩小范围避免浪费精力。1.3 6 个工具的分工表工具关注点典型命令/入口适合场景jpsJava 进程jps -l -v找目标进程 pidjstatGC、类加载、编译jstat -gcutil pid 1000 10判断 GC 频率与内存趋势jmap堆内存信息与 dumpjmap -heap pid/-dump查看堆配置、对象分布、OOM 排查jstack线程状态与死锁jstack -l pid看线程阻塞、死锁、CPU 高线程JConsoleJMX 可视化监控jconsole pid看堆/线程/类趋势远程监控VisualVM采样、堆转储、插件jvisualvm生成实时抽样分析堆快照加上后面要讲的 Arthas这个矩阵基本覆盖日常 90% 的 JVM 问题。2. jps 与 jstat先用命令行把“现场”稳住2.1 jps找进程是第一步别用 ps 硬猜很多人会用ps -ef | grep java来确认进程这没问题但输出比较长也不够结构化。JDK 自带jps就是干这个的它只列出 Java 进程还能直接看到传给 JVM 的启动参数。常用方式# 显示 pid 和主类名 jps -l # 显示 pid 和启动参数注意 JVM 参数也被打印出来 jps -v我在生产环境一般会组合使用jps -l -v | grep payment这样能快速看到支付服务对应的 pid以及它的-Xmx、-Xms、GC 收集器参数。曾经有个生产环境配置了-Xmx4g但宿主机只有 4g 内存导致频繁发生 OS 级 swap后来就是通过jps -v当场发现参数和容器规格不匹配才避免继续踩坑。注意在容器环境里jps有时看不到其他命名空间的 Java 进程或者只能看到自己。这通常是/proc挂载隔离导致的不一定是你命令敲错了。2.2 jstatGC 数据一眼定方向拿到 pid 之后我一般不会直接 dump 线程而是先看 GC。因为很多“接口变慢 CPU 高”的问题本质是 JVM 在疯狂做垃圾回收。最常用的命令# 每隔 1 秒输出一次 GC 统计共输出 10 次 jstat -gcutil pid 1000 10输出示例S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 0.00 62.40 78.45 92.30 88.10 18234 152.345 6 18.672 171.017 0.00 0.00 65.12 79.20 92.30 88.10 18234 152.345 6 18.672 171.017重点看几个值EEden 区使用率如果频繁从很低冲到 100%说明对象创建速度极快O老年代使用率如果只增不减大概率有对象晋升后一直无法回收YGC/FGCYoung GC 和 Full GC 的次数YGCT/FGCT对应的累计耗时。如果 FGC 次数在增加且 FGCT 涨得很快系统性能必然受影响。上面的输出里老年代O稳定在 78% 左右Full GC 总共 6 次还没有到“病危”的程度但如果 10 次采样里FGC一直在涨那就得警惕了。2.3 从 jstat 输出判断下一步动作有一次排查一个工单系统我看到O从 60% 跳到 95%紧接着FGC从 1 变成 3老年代占用却没有明显下降。这就说明大量对象进入老年代且 Full GC 回收不了它们。此时不用怀疑大概率是内存泄漏或者大对象缓存没释放。于是我用jmap -histo一看果然有个HashMap实例对象数量异常大占了 40% 以上的堆空间再结合业务代码发现是用户 Session 缓存忘记清理了。所以我的习惯是jstat先看“是不是 GC 的问题”如果 GC 正常再往线程和代码方向找如果 GC 异常则优先查堆和对象。3. jmap 与 jstack内存和线程问题取证的黄金搭档3.1 jmap查看堆信息和导出堆快照jmap是了解堆内存的利器但也是几个工具里“风险”最高的因为 dump 大堆时会导致服务停顿。所以我通常先执行只读命令不直接 dump# 查看堆内存分配情况和当前使用率 jmap -heap pid输出包括Heap Configuration新生代、老年代大小等和Heap Usage各个区域当前使用率。这能帮你快速确认当前各代大小是否合理。比如 Eden 区设置过小对象刚创建就频繁 Minor GC对象很快就晋升到老年代老年代又扛不住最终导致 Full GC 越来越频繁。如果怀疑某个对象占用过多先看对象直方图# 按对象占用大小排序取前 30 行 jmap -histo:live pid | head -30注意:live参数会触发一次 Full GC在堆很大的生产环境要谨慎最好在低峰期执行。不加:live则只统计当前堆中的对象不会主动触发 GC风险更小。确定需要离线分析时再导出堆快照jmap -dump:live,formatb,file/tmp/heap.hprof pid导出后的.hprof文件可以用 VisualVM、MAT 或 JProfiler 打开。个人建议优先用 MAT 的 Leak Suspects 功能它会自动帮你找“谁占着内存不释放”。3.2 jstack用线程 ID 把“元凶”从线程栈里揪出来jstack最经典的场景是配合top定位 CPU 占用最高的线程。步骤如下# 找出 pid 内 CPU 占用最高的线程 top -Hp pid假设top输出里有个线程 pid 为28572CPU 占用 98%先把它转成 16 进制printf %x\n 28572得到6f9c。然后用jstack抓线程快照并搜索这个线程 IDjstack -l pid /tmp/thread.log grep -A 20 nid0x6f9c /tmp/thread.log此时你会看到这个线程当前正在执行的方法栈。实战里我曾用这套方法定位过一个“看似在搞业务其实在疯狂轮询空集合”的问题。线程栈里显示线程一直卡在某个while (list.size() 0)循环里CPU 自然就爆了。另一个常用场景是死锁检测。直接抓完整线程快照文件尾部会显示Found one Java-level deadlock: ...如果没有显示也可以用 JConsole 的“检测死锁”按钮更直观。3.3 如何判断是内存泄漏还是“只是内存不够”这个是我经常被问到的点。jmap和jstat数据都拿回来后到底怎么判断我的经验是看两件事看趋势jstat -gcutil多采样几次如果老年代O在 YGC 之后不降反升每次 Full GC 后也只降一点点说明有对象被长期引用垃圾回收不掉基本是泄漏。看jmap -histo的 Top 对象如果某个业务类或缓存类实例数量巨大可以直接顺着对象的包名去代码里查引用。如果是“内存不够”通常老年代使用率会在 Full GC 后降到较低水平但很快又涨上来这种往往是存活对象多或者吞吐量峰值高优先考虑调大堆或者调整 GC 收集器而不是急着找泄漏点。4. JConsole 与 VisualVM不用盲猜图表会说话4.1 JConsoleJDK 自带的“仪表盘”命令行工具适合快速取证但如果你需要观察一段时间的趋势JConsole 更趁手。直接执行jconsole pid就能打开 GUI 界面。里面能看到堆内存、非堆内存、线程数、类加载数、CPU 占用率的实时曲线。我尤其喜欢它的“线程”页签。在排查一个 Dubbo 线程池耗尽问题时我用 JConsole 看到线程数像心电图一样抖动但始终没有降下来。再点“检测死锁”屏幕上直接弹出哪个线程持有锁、哪个线程在等待锁省去了在 jstack 日志里大海捞针。不过 JConsole 也有个问题默认只能连接本机或有 JMX 远程配置的进程而且 GUI 在无图形化的服务器上没法用。这时候可以通过 SSH 端口转发把远程 JMX 端口拉到本地再连。4.2 VisualVM从采样到堆转储的一条龙工具VisualVM 是我个人觉得 JDK 时代最被低估的工具。它在 JDK 6/7/8 里都自带目录在$JAVA_HOME/bin/jvisualvm。JDK 9 之后不再是默认自带需要单独下载但功能更强了。VisualVM 的核心功能实时监控和 JConsole 类似但展示更友好还会显示类的实例数和大小CPU/内存抽样不用像jmap那样 dump就可以定时收集方法调用耗时和内存分配热点对生产环境更友好堆转储分析打开.hprof文件能看到对象引用链插件机制比如 BTrace 插件当然现在已经被 Arthas 取代得差不多了。我之前处理过一个“内存缓慢增长”的服务直接用 VisualVM 对进程做 5 分钟采样最后在“内存抽样”结果里看到一个自定义缓存类占了大头。对比代码后发现缓存容器用static保存了所有历史订单号而且因为软引用误用一直没被回收。整个过程没有触发一次 Full GC对线上影响很小。4.3 可视化工具有哪些“坑”可视化工具虽然直观但连接生产环境时要注意远程 JMX 必须配置认证不然等于把 JVM 的“后门”暴露出去不要在生产大堆服务上直接做堆转储VisualVM 的“堆 Dump”按钮看起来很简单但 dump 一个 8GB 堆的瞬间服务极易卡死。真要做用jmap -dump:live 低峰期或者先用采样功能缩小范围容器环境下VisualVM 可能无法通过宿主机 IP 直连需要先进入容器内部再抓监控数据。5. Arthas定位到方法级解决问题更快5.1 为什么说 Arthas 是“加餐里的主菜”严格来说正文对应的 6 个工具是 jps、jstat、jmap、jstack、JConsole、VisualVM。但在真实工作中我的最终武器其实是 Arthas。它是一个 Java 在线诊断工具能让你在不重启服务、不改代码的情况下动态地查看类加载情况、方法调用参数、返回结果、执行耗时甚至直接执行表达式。安装很简单curl -O https://arthas.aliyun.com/arthas-boot.jar java -jar arthas-boot.jar然后选择目标进程进去就进入 Arthas 命令行。相比前面的 6 个工具Arthas 的优势是“精准到方法级”。你不需要猜直接盯住某个方法看它是不是瓶颈。5.2 dashboard、thread、watch、trace四个最常用的命令进入 Arthas 后我几乎必用dashboarddashboard它就像 JVM 版的top一屏显示线程、内存、GC、类加载的实时状态比jstat直观。如果我不想刷屏就用thread -n 3直接查看 CPU 占用最高的 3 个线程并打印它们的调用栈。这一步替代了 jstack 里很多手工操作。接下来是trace和watch这两个命令是排查方法级问题的“神兵”。比如一个接口偶发超时但不知道耗时耗在哪个子调用上可以这样trace com.example.OrderService createOrder然后调用一次该接口Arthas 会打印整个方法内部各子调用的耗时分布一眼就能看出是数据库查询慢还是 Redis 调用慢又或者是本地计算阻塞。想查看某个方法的入参和返回值用watch com.example.OrderService createOrder {params, returnObj} -x 2这个命令会拦截实际请求打印每次调用的参数和返回结果对排查“某个用户数据就是不对”的问题极好用。5.3 和 JDK 自带工具搭配的节奏Arthas 也不是万能的一是它的字节码增强本身有一定性能开销二是如果 JVM 已经严重 OOM 到几乎无法响应Arthas 也可能连不上。所以我通常这样搭配先用 jps/jstat/jstack/jmap 做第一轮快速判断确定大致方向后再上 Arthas 做方法级深挖如果需要长时间观察趋势再用 JConsole 或 VisualVM 辅助。6. 一套少走弯路的 JVM 问题排查实战流程6.1 完整案例从 CPU 告警到代码定位我拿最近一次实际案例还原一下整个流程。某商户中心服务告警CPU 超过 85%请求成功率下降。jps -l -v找到对应服务的 pid同时确认启动参数没有明显错误jstat -gcutil pid 1000 5发现 YGC 频繁但 FGC 不多排除 Full GC 压力top -Hp pid发现一个线程 CPU 占用 300%多核。用printf %x转成十六进制再用jstack找到该线程栈发现线程卡在某个 JSON 序列化工具的writeString方法继续看业务代码发现一个日志打印语句用了JSON.toJSONString()把整个大对象打出来。这个对象底层有一个巨大的链表结构每次接口调用都会触发一次深层次序列化线程就这么“烧”起来了为了验证用 Arthaswatch观察该方法的入参大小确认传入对象异常巨大最终改成只打印关键字段并给日志加长度限制。CPU 立刻降回 20% 以下。你看这个案例里没有用到很高深的技术纯粹是“按顺序排查 每步用对工具”。6.2 不同场景下工具选择的优先级症状首选工具备选进程不存在/一直重启jps、操作系统日志jstatCPU 高jstack top -HpArthas thread内存占用高jstat、jmap -histoVisualVM 抽样接口变慢/卡顿jstack、jstatArthas trace老年代持续增长jmap -histo、jstatMAT 分析 dump线程死锁jstack -lJConsole 死锁检测6.3 避坑清单这些错误我基本都犯过不要一开始就 dump 大堆。先jmap -histo或 VisualVM 采样定位到一个大范围再考虑 dump。否则拉取一个 10G 堆文件的时间足够线上再出一轮事故。jmap -histo:live会触发 Full GC高峰期慎用。非要用加上nohup等方式避免终端断开影响。jstack看到线程 ID 时记得是十六进制的nid不是十进制的 tid。头几次最容易在这里卡住。JConsole 远程连接要开-Dcom.sun.management.jmxremote.port、-Dcom.sun.management.jmxremote.authenticatetrue别图省事关闭鉴权。JDK 8 和 JDK 11 的垃圾回收器默认值不同导致同样的工具输出解读标准不一样。排查前先确认 JDK 版本别把 G1 的老年代增长直接按 CMS 的逻辑套。6.4 我的个人习惯每次排查都留下“快照”最后分享一个我自己的习惯每次排查 JVM 问题时我都会把jstack输出、jstat采样、jmap -histo结果按时间戳保存到本地一个目录。即使当下问题解决这些数据也是宝贵的基线。下次遇到“看起来不一样”的问题时我会把两次快照做对比很多隐蔽的性能劣化就是这么暴露出来的。JVM 排查这件事工具只是敲门砖真正的能力来自对每个输出指标的长期理解和积累。
返回列表