Java 应用线上问题排查思路、工具小结

时间 2020-05-01

标签 java 应用线上问题排查思路工具小结栏目 Java 繁體版

原文原文链接

原文地址： Java 应用线上问题排查思路、工具小结
原创不易，转载请注明出处。html

前言

本文总结了一些常见的线上应急现象和对应排查步骤和工具。分享的主要目的是想让对线上问题接触少的同窗有个预先认知，省得在遇到实际问题时手忙脚乱。毕竟做者本身也是从手忙脚乱时走过来的。java

只不过这里先提示一下。在线上应急过程当中要记住，只有一个整体目标：尽快恢复服务，消除影响。无论处于应急的哪一个阶段，咱们首先必须想到的是恢复问题，恢复问题不必定可以定位问题，也不必定有完美的解决方案，也许是经过经验判断，也许是预设开关等，但均可能让咱们达到快速恢复的目的，而后保留部分现场，再去定位问题、解决问题和复盘。git

在大多数状况下，咱们都是先优先恢复服务，保留下当时的异常信息（内存dump、线程dump、gc log等等，在紧急状况下甚至能够不用保留，等到过后去复现），等到服务正常，再去复盘问题。github

好，如今让咱们进入正题吧。sql

常见现象：CPU 利用率高/飙升

场景预设：shell

监控系统忽然告警，提示服务器负载异常。数据库

预先说明：安全

CPU飙升只是一种现象，其中具体的问题可能有不少种，这里只是借这个现象切入。服务器

注：CPU使用率是衡量系统繁忙程度的重要指标。可是 CPU使用率的安全阈值是相对的，取决于你的系统的IO密集型仍是计算密集型。通常计算密集型应用CPU使用率偏高load偏低，IO密集型相反。

常见缘由：网络

频繁 gc
死循环、线程阻塞、io wait...etc

模拟

这里为了演示，用一个最简单的死循环来模拟CPU飙升的场景，下面是模拟代码，

在一个最简单的SpringBoot Web 项目中增长CpuReaper这个类，

/**
 * 模拟 cpu 飙升场景
 * @author Richard_yyf
 */
@Component
public class CpuReaper {

    @PostConstruct
    public void cpuReaper() {
        int num = 0;
        long start = System.currentTimeMillis() / 1000;
        while (true) {
            num = num + 1;
            if (num == Integer.MAX_VALUE) {
                System.out.println("reset");
                num = 0;
            }
            if ((System.currentTimeMillis() / 1000) - start > 1000) {
                return;
            }
        }
    }
}

打包成jar以后，在服务器上运行。java -jar cpu-reaper.jar &

第一步：定位出问题的线程

方法 a: 传统的方法

top 定位CPU 最高的进程
执行top命令，查看全部进程占系统CPU的排序，定位是哪一个进程搞的鬼。在本例中就是我们的java进程。PID那一列就是进程号。(对指示符含义不清楚的见【附录】)
top -Hp pid 定位使用 CPU 最高的线程
printf '0x%x' tid 线程 id 转化 16 进制
```
> printf '0x%x' 12817
> 0x3211
```
jstack pid | grep tid 找到线程堆栈
```
> jstack 12816 | grep 0x3211 -A 30
```

方法 b: show-busy-java-threads

这个脚原本自于github上一个开源项目，项目提供了不少有用的脚本，show-busy-java-threads就是其中的一个。使用这个脚本，能够直接简化方法A中的繁琐步骤。以下，

> wget --no-check-certificate https://raw.github.com/oldratlee/useful-scripts/release-2.x/bin/show-busy-java-threads
> chmod +x show-busy-java-threads

> ./show-busy-java-threads

show-busy-java-threads
# 从全部运行的Java进程中找出最消耗CPU的线程（缺省5个），打印出其线程栈

# 缺省会自动从全部的Java进程中找出最消耗CPU的线程，这样用更方便
# 固然你能够手动指定要分析的Java进程Id，以保证只会显示你关心的那个Java进程的信息
show-busy-java-threads -p <指定的Java进程Id>

show-busy-java-threads -c <要显示的线程栈数>

方法 c: arthas `thread`

阿里开源的arthas如今已经几乎包揽了咱们线上排查问题的工做，提供了一个很完整的工具集。在这个场景中，也只须要一个thread -n 命令便可。

> curl -O https://arthas.gitee.io/arthas-boot.jar # 下载

要注意的是，arthas的cpu占比，和前面两种cpu占比统计方式不一样。前面两种针对的是Java进程启动开始到如今的cpu占比状况，arthas这种是一段采样间隔内，当前JVM里各个线程所占用的cpu时间占总cpu时间的百分比。
具体见官网：https://alibaba.github.io/art...

后续

经过第一步，找出有问题的代码以后，观察到线程栈以后。咱们就要根据具体问题来具体分析。这里举几个例子。

状况一：发现使用CPU最高的都是GC 线程。

GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007fd99001f800 nid=0x779 runnable
GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007fd990021800 nid=0x77a runnable 
GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007fd990023000 nid=0x77b runnable 
GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007fd990025000 nid=0x77c runnabl

gc 排查的内容较多，因此我决定在后面单独列一节讲述。

状况二：发现使用CPU最高的是业务线程

io wait
- 好比此例中，就是由于磁盘空间不够致使的io阻塞
等待内核态锁，如 synchronized
- jstack -l pid | grep BLOCKED 查看阻塞态线程堆栈
- dump 线程栈，分析线程持锁状况。
- arthas提供了thread -b，能够找出当前阻塞其余线程的线程。针对 synchronized 状况

常见现象：频繁 GC

1. 回顾GC流程

在了解下面内容以前，请先花点时间回顾一下GC的整个流程。

接前面的内容，这个状况下，咱们天然而然想到去查看gc 的具体状况。

方法a : 查看gc 日志
方法b : jstat -gcutil 进程号统计间隔毫秒统计次数（缺省表明一致统计
方法c : 若是所在公司有对应用进行监控的组件固然更方便（好比Prometheus + Grafana）

这里对开启 gc log 进行补充说明。一个经常被讨论的问题（惯性思惟）是在生产环境中GC日志是否应该开启。由于它所产生的开销一般都很是有限，所以个人答案是须要开启。但并不必定在启动JVM时就必须指定GC日志参数。

HotSpot JVM有一类特别的参数叫作可管理的参数。对于这些参数，能够在运行时修改他们的值。咱们这里所讨论的全部参数以及以“PrintGC”开头的参数都是可管理的参数。这样在任什么时候候咱们均可以开启或是关闭GC日志。好比咱们可使用JDK自带的jinfo工具来设置这些参数，或者是经过JMX客户端调用 HotSpotDiagnostic MXBean的setVMOption方法来设置这些参数。
这里再次大赞arthas❤️，它提供的vmoption命令能够直接查看，更新VM诊断相关的参数。

获取到gc日志以后，能够上传到GC easy帮助分析，获得可视化的图表分析结果。

2. GC 缘由及定位

prommotion failed

从S区晋升的对象在老年代也放不下致使 FullGC（fgc 回收无效则抛 OOM）。

可能缘由：

survivor 区过小，对象过早进入老年代
查看 SurvivorRatio 参数
大对象分配，没有足够的内存
dump 堆，profiler/MAT 分析对象占用状况
old 区存在大量对象
dump 堆，profiler/MAT 分析对象占用状况

你也能够从full GC 的效果来推断问题，正常状况下，一次full GC应该会回收大量内存，因此 正常的堆内存曲线应该是呈锯齿形。若是你发现full gc 以后堆内存几乎没有降低，那么能够推断： 堆中有大量不能回收的对象且在不停膨胀，使堆的使用占比超过full GC的触发阈值，但又回收不掉，致使full GC一直执行。换句话来讲，多是内存泄露了。

通常来讲，GC相关的异常推断都须要涉及到内存分析，使用jmap之类的工具dump出内存快照（或者 Arthas的heapdump）命令，而后使用MAT、JProfiler、JVisualVM等可视化内存分析工具。

至于内存分析以后的步骤，就须要小伙伴们根据具体问题具体分析啦。

常见现象：线程池异常

场景预设：

业务监控忽然告警，或者外部反馈提示大量请求执行失败。

异常说明：

Java 线程池以有界队列的线程池为例，当新任务提交时，若是运行的线程少于 corePoolSize，则建立新线程来处理请求。若是正在运行的线程数等于 corePoolSize 时，则新任务被添加到队列中，直到队列满。当队列满了后，会继续开辟新线程来处理任务，但不超过 maximumPoolSize。当任务队列满了而且已开辟了最大线程数，此时又来了新任务，ThreadPoolExecutor 会拒绝服务。

常见问题和缘由

这种线程池异常，通常能够经过开发查看日志查出缘由，有如下几种缘由：

下游服务响应时间（RT）过长
这种状况有多是由于下游服务异常致使的，做为消费者咱们要设置合适的超时时间和熔断降级机制。

另外针对这种状况，通常都要有对应的监控机制：好比日志监控、metrics监控告警等，不要等到目标用户感受到异常，从外部反映进来问题才去看日志查。
数据库慢 sql 或者数据库死锁
查看日志中相关的关键词。
Java 代码死锁
jstack –l pid | grep -i –E 'BLOCKED | deadlock'

4、常见问题恢复

这一部份内容参考自此篇文章

对于上文提到的一些问题，这里总结了一些恢复的方法。

5、Arthas

这里仍是想单独用一节安利一下Arthas这个工具。

Arthas 是阿里巴巴开源的Java 诊断工具，基于 Java Agent 方式，使用 Instrumentation 方式修改字节码方式进行 Java 应用诊断。

dashboard ：系统实时数据面板, 可查看线程，内存，gc 等信息
thread ：查看当前线程信息，查看线程的堆栈，如查看最繁忙的前 n 线程
getstatic：获取静态属性值，如 getstatic className attrName 可用于查看线上开关真实值
sc：查看 jvm 已加载类信息，可用于排查 jar 包冲突
sm：查看 jvm 已加载类的方法信息
jad：反编译 jvm 加载类信息,排查代码逻辑没执行缘由
logger：查看logger信息，更新logger level
watch：观测方法执行数据，包含出参、入参、异常等
trace：方法内部调用时长，并输出每一个节点的耗时，用于性能分析
tt：用于记录方法，并作回放

以上内容节选自 Arthas官方文档。

另外，Arthas里的还集成了 ognl 这个轻量级的表达式引擎，经过ognl，你能够用arthas 实现不少的“骚”操做。

其余的这里就很少说了，感兴趣的能够去看看arthas的官方文档、github issue。

6、涉及工具

再说下一些工具。

Arthas（超级推荐❤️❤️）
useful-scripts
GC easy
Smart Java thread dump analyzer - thread dump analysis in seconds
PerfMa - Java虚拟机参数/线程dump/内存dump分析
Linux 命令
Java N 板斧
MAT、JProfiler...等可视化内存分析工具

结语

我知道我这篇文章对于线上异常的概括并不全面，还有网络（超时、TCP队列溢出...）、堆外内存等不少的异常场景没有涉及。主要是由于本身接触不多，没有深入体会研究过，强行写出来免不得会差点意思，更怕的是误了别人😅。

还有想说的就是，Java 应用线上排查实际很是考究一我的基础是否扎实、解决问题能力是否过关。好比线程池运行机制、gc分析、Java 内存分析等等，若是基础不扎实，看了更多的是一头雾水。另外就是，多看看网上一些有实际场景的关于异常排查的经验文章，学习他们解决排查问题的思路和工具。这样即便本身暂时遇不到，可是会在脑海里面慢慢总结出一套解决相似问题的结构框架，到时候真的遇到了，也就是举一反三的事情罢了。

若是本文有帮助到你，但愿能点个赞，这是对个人最大动力🤝🤝🤗🤗。

参考

https://developer.aliyun.com/...
Arthas 3.2.0 文档
《分布式服务架构：原理、设计与实战》

附录

top 命令显示的指示符的含义

指示符	含义
PID	进程id
USER	进程全部者
PR	进程优先级
NI	nice值。负值表示高优先级，正值表示低优先级
VIRT	进程使用的虚拟内存总量，单位kb。VIRT=SWAP+RES
RES	进程使用的、未被换出的物理内存大小，单位kb。RES=CODE+DATA
SHR	共享内存大小，单位kb
S	进程状态。D=不可中断的睡眠状态 R=运行 S=睡眠 T=跟踪/中止 Z=僵尸进程
%CPU	上次更新到如今的CPU时间占用百分比
%MEM	进程使用的物理内存百分比
TIME+	进程使用的CPU时间总计，单位1/100秒
COMMAND	进程名称（命令名/命令行）