串一串

Java常见线上故障排查方案

[Toc]

一、前言

在软件开发过程中，排查和修复产线问题是每一位工程师都需要掌握的基本技能。但是在生产环境中，程序代码、硬件、网络、协作软件等任一因素，都会引发意想不到的问题，所以排查产线问题通常都是比较困难的，所以问题的定位体现了一名工程师的基础能力，问题的解决则体现了工程师的技能素养。

以下从5个方面分享产线常见问题的排查手段：

1. Java常见线上问题总结
2. 如何定位问题
3. APM链路跟踪分析
4. 常用Linux分析命令
5. Arthas（阿尔萨斯）诊断命令
6. JVM问题定位命令
7. GC分析

二、常见线上故障总结

绝大多数Java线上问题从表象来看通常可以归纳为6个方面：代码、CPU、内存、磁盘、网络、中间件。比如，应用上线后突然CPU使用率99%、内存泄漏、STW时间过长，这些问题通常可以分为四大类：

• 系统问题
  • CPU占用率过高
  • 磁盘使用率过高
  • 内存消耗过高
  • 网络异常
• 服务问题
  • 服务突然宕机
  • 服务调用超时
  • 流量拥挤
• 代码问题
  • Error
  • Exception
  • 并发脏数据&死锁
  • 依赖资源冲突
• 依赖问题
  • 数据库连接问题
  • 中间件不可用

三、如何定位问题

我们如果想解决系统故障，首先要定位到发生故障的原因，排查手段一般包括以下几项，也可以将此理解为排查顺序：

1. 业务日志分析排查
2. APM分析排查
3. 外部环境排查
4. 应用服务排查
5. 云厂商或运营商问题排查

3.1、业务日志分析排查

通常情况下，日志是故障案发的第一现场，大部分错误信息都会在业务日志上有所体现，比如看看下面这段代码：

这段代码使用了并发流将数据加入到一个List中，乍一看代码不会出现什么问题，但是在运行过程中却未能按照预期返回结果，此时我们查看日志，发现日志中输出了一段异常信息，具体异常栈信息如下：

通过日志可以看到出错的位置在TaskServiceImpl.java文件的第75行代码上，错误信息是java.lang.ArrayIndexOutOfBoundsException:163，这就是问题定位，整体描述出来就是：在TaskServiceImpl.java文件中第75行代码上出现了数组越界异常，引起异常的原因是在调用java.util.ArrayList#add()方法时因为并发请求导致没有动态扩展数组容量。

为什么我们能够直接描述出来是在调用ArrayList#add()方法时因为并发请求导致的没有动态扩展数组容量呢？因为我们结合ArrayList的内部实现原理及动态扩容的特性，可以知道在单线程的情况下，代码是串行执行，ArrayList内的数组都会是先扩容再插入，所以不会出现数组越界的错误，既然单线程不会引起该错误，那一定就是多线程并发造成的了，解决方案就是给代码加锁或者由并发流改为串行流，就是这么简单。

通过上面的分析，教育了我们一件事情：一定要在关键代码逻辑位置输出相关日志，尤其是在代码可能发生异常的地方，一定要将日志输出到文件中，只有这样才更利于我们在发生错误时进行排查。

但是业务日志较优于解决单体服务异常，但现在的应用通常使用的是分布式架构，而在分布式系统中，仅通过单服务节点的日志，很难将错误信息与请求链路关联在一起，也就是通过系统中某个服务的异常日志信息很难定位到问题的根本原因。并且我们还需要关注各服务执行过程中的耗时情况，及时的发现异常服务，并根据异常信息进行修复。要满足这种需求，仅通过分析单个服务的日志信息是不够的，此时则需要APM进行全链路分析，通过请求链路监控，实时的发现链路中相关服务的异常情况。

3.2、APM分析排查

我们先看一下什么是APM(Application Performance Management)，应用性能管理器，目的是通过各种探针采集数据，收集关键指标，同时搭配数据呈现以实现对应用程序性能管理和故障管理的系统化解决方案。通过分布式链路调用跟踪系统，通过在系统请求中透传 traceId，将所有相关日志进行聚合，然后日志统一采集和分析后，以图形化的形式展示给工程师们，而他们在排查问题的时候，可以简单粗暴且直观的调度出问题最根本的原因。

业务流程图

实现架构图

此处我们使用的是Skywalking，这是一款在Java应用中使用较为广泛的APM，下面我们从几个方向来简单介绍一下Skywalking的使用。

3.2.1 仪表盘

• 控制台中的仪表盘常规、服务、服务实例等Panel以供我们排查信息，在每一个Panel中都为我们提供一些有用的指标信息，我们也可以在Panel内自定义Item来实现精准显示。

  

• 除了服务相关的指标之外，还为我们监控了所有服务中使用的数据库的指标数据，此处不仅仅是我们使用到的MySQL、Oracle等关系型数据库，还可以监控MongoDB、Elasticsearch等非关系型数据库

  

3.2.2 拓扑图

在拓扑图中可以查看具体服务的依赖服务关系，还能查看到服务之间请求的请求时间、吞吐量和SLA等数据，可以依据这些指标进行服务依赖关系排查，此模块就不做过多介绍，可以自己搭建了玩一玩。

3.2.3 链路追踪

接下来我们介绍一下追踪功能，这应该是我们使用Skywalking所有功能中最多的一个，这也是我们上面提到的请求链路追踪功能，我们把目光切换到下面的图片上。下面这张图很容易读懂，上侧是筛选功能块，左侧是接口执行情况，右侧为接口的请求链路及各路请求耗时详细，页面的布局大致如此。图片告诉我们有一些接口耗时较高，甚至达到了193秒，选中我们要查看的接口，右侧会自动罗列出该接口的调用链，可以看到本次请求中数据库execute方法耗时较长，达到了60秒，点击右侧对应的item，就会弹窗出具体执行的SQL语句，我们接下来就可以根据SQL语句进行问题解决，是不是很轻松？

Skywalking还有很多强大的功能，我们这里就不一一介绍了，并且目前市场上也有很多强大的APM工具，使用较多的有如下几个，大家可以根据自己项目产品的情况选择最适合自己的：

Apache Skywalking：https://skywalking.apache.org/

Pinpoint：https://pinpoint.com/product/for-engineers

SpringCloud Zipkin：https://docs.spring.io/spring-cloud-sleuth/docs/current-SNAPSHOT/reference/html/#sending-spans-to-zipkin

3.3、物理环境排查

物理环境是指服务所依附的物理环境，如服务器、宿主机、容器等，细分为服务器负载、CPU、内存、磁盘、网络几个方面。

3.3.1 CPU分析

排查CPU的目的主要是查看服务器CPU的使用率， 使用top命令分析CPU使用情况，进入top命令窗口后按P(注意大写，Progress首字母)查看CPU占用最高的进程信息，如若是Java进程占CPU比例较高，则可以继续通过top -Hp命令查看详细的线程信息，然后打印该线程的堆栈信息进行排查。具体执行指令为：

# 查看进程
top -c
# 查看某进程的线程
top -Hp <pid>
# 十进制转16进制
printf '%x\n' <十进制数>
# 查看线程堆栈信息
jstack <pid> | grep '0x十六进制数' -C5 --color

3.3.2 内存分析

使用free -h或free -m命令查看内存使用情况，区别就是前者以GB为单位，后者以MB为单位，本人喜欢用-h，但是该命令只能查看到当前机器的内存使用情况，并推断出是不是因系统内存不足引起的故障，如果想要了解具体服务应用的内存使用情况，还是需要先找到服务对应的进程ID，然后通过top命令，然后按M(注意大写，Memory首字母)查看内存占用最大的进程信息。

3.3.3 磁盘分析

使用df、du、iostat、lsof等命令查看磁盘IO情况，找到读写异常的进程，这里就不做具体的过程介绍了，分享一个小命令：

# 查看指定目录下所有文件和子目录的大小
# 首先进入到要查看的目录
cd ~
# 执行改语句等待结果显示，一般都很快
du -sh *

3.3.4 网络分析

使用dstat、vmstat等命令查看网络流量、TCP连接等情况，分析异常流量

3.4、应用服务排查

应用排查，排查应用本身最有可能引发的问题，针对各种场景进行对应分析

3.4.1 CPU分析

使用jstack等命令进行JVM分析，下面会有详细的介绍。

3.4.2 内存分析

使用jmap等命令分析内存使用情况，下面也会有详细的介绍，大概在第六小节。

3.5、云厂商或运营商问题排查

排查到了这一步的话，只需关注云厂商或运营商官方公告即可。

假设我们从业务日志、APM分析中都没分析出问题所在，那么此时基本只能连接到生产环境中进行排查了。根据上面的外部排查方案，这里简单复习下常用的Linux分析命令以便从系统层面上分析。

四、常用Linux分析命令

针对外部环境排查，需要使用的常用Linux分析命令包括 : top、free、df、lsof、dstat、vmstat等，简单介绍如下：

4.1 CPU

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

top命令是Linux下常用的 CPU 性能分析工具，能够实时显示系统中各个进程的资源占用状况，常用于服务端性能分析。

top

top 命令显示了各个进程 CPU 使用情况，一般 CPU 使用率从高到低排序展示输出。其中 Load Average 显示最近1分钟、5分钟和15分钟的系统平均负载，上图各值为3.4、3.31、3.46。

我们一般会关注 CPU 使用率最高的进程，正常情况下就是我们的应用主进程。第七行以下：各进程的状态监控，参数说明：

• PID : 进程id
• USER : 进程所有者的用户名
• PR : 进程优先级
• NI : nice值。负值表示高优先级，正值表示低优先级
• VIRT : 进程使用的虚拟内存总量，单位kb
• SHR : 共享内存大小
• %CPU : 上次更新到现在的CPU时间占用百分比
• %MEM : 进程使用的物理内存百分比
• TIME+ : 进程使用的CPU时间总计，单位1/100秒
• COMMAND : 命令名称、命令行

4.2 内存

内存是排查线上问题的重要参考依据，free 是显示的当前内存的使用，-h 表示人类可读性。

free -h

参数说明：

• total ：内存总数

• used：已经使用的内存数

• free：空闲的内存数

• shared：被共享使用的物理内存大小

• buffers/buffer：被 buffer 和 cache 使用的物理内存大小

• available： 还可以被应用程序使用的物理内存大小

4.3 磁盘

磁盘满了很多时候会引发系统服务不可用等问题

df -h

4.4 网络

dstat 是一个可以取代vmstat，iostat，netstat和ifstat这些命令的多功能产品。

dstat

默认情况下，dstat每秒都会刷新数据。需要注意的是报告的第一行，由于dstat会通过上一次的报告来给出一个总结，所以第一次运行时是没有平均值和总值的相关数据。

默认输出解释：

CPU状态：显示了用户，系统和空闲部分，便于分析CPU当前的使用状况

磁盘统计：磁盘的读写操作，显示磁盘的读、写总数。

网络统计：网络设备发送和接受的数据，显示了网络收、发数据总数。

分页统计：系统的分页活动。

系统统计：这一项显示的是中断（int）和上下文切换（csw）。

到了这一步，如果CPU、内存、磁盘、网络这四个地方都没有问题的话，那就进入了应用本身的问题排查阶段。下一步就该使用jvm命令进行问题定位了，但很多研发可能由于自身工作经验不足、对Java内存模型理解不深、尚未掌握Jvm排查命令等原因对Jvm相关排查畏手畏脚，不够自信，进而影响排查进度。针对这种情况，本文推荐一款开源的Java诊断工具，对Jvm不熟的研发可以尝试学习使用下。相对Jvm命令来说简单多了。

五、Arthas诊断命令

Arthas 是Alibaba开源的Java诊断工具，深受开发者喜爱。

当你遇到以下类似问题而束手无策时，Arthas 可以帮助你解决：

• 这个类从哪个 jar 包加载的？为什么会报各种类相关的 Exception？
• 我改的代码为什么没有执行到？难道是我没 commit？分支搞错了？
• 遇到问题无法在线上 debug，难道只能通过加日志再重新发布吗？
• 线上遇到某个用户的数据处理有问题，但线上同样无法 debug，线下无法重现！
• 是否有一个全局视角来查看系统的运行状况？
• 有什么办法可以监控到JVM的实时运行状态？
• 怎么快速定位应用的热点，生成火焰图？

Arthas支持JDK 6+，支持Linux、Mac、Winodws，采用命令行交互模式，同时提供丰富的 Tab 自动补全功能，进一步方便进行问题的定位和诊断。

5.1 下载安装

curl -O https://alibaba.github.io/arthas/arthas-boot.jar

5.2 启动Arthas

java -jar arthas-boot.jar # 此处需要联网，因为arthas需要下载相关依赖，也可以将别的机器下载好的依赖拷贝到目标机器

arthas 会列出已存在的Java进程，并提醒输入序号，键入回车，进入arthas 诊断界面。

5.3 开始诊断

按照提醒，这里输入需要诊断的序号，输入回车，响应界面如下：

5.4 查看dashboard

输入dashboard【支持Tab补全命令】，输入回车，会展示当前系统的实时面板，按ctrl+c可以中断执行。

上图线上了当前系统对应的线程、内存（分代）、GC、Runtime的各项信息。

除了dashboard命令外，arthas还有许多常用命令，这里挑一些做简单说明。

5.5 arthas常见命令介绍

• jvm 查看当前 JVM 的信息
• thread 查看当前 JVM 的线程堆栈信息，-b选项可以一键检测死锁
• trace 方法内部调用路径，并输出方法路径上的每个节点上耗时，服务间调用时间过长时使用
• stack 输出当前方法被调用的调用路径
• Jad 反编译指定已加载类的源码，反编译便于理解业务
• logger 查看和修改logger，可以动态更新日志级别。

这里只列出常用命令，完整列表参考命令列表：https://alibaba.github.io/arthas/commands.html。

arthas使用上相对JVM命令简单很多，即便是工作年限不多的小伙伴学起来也很快。熟练使用arthas应该能诊断出大部分线上应用问题，但生产环境通常不允许擅自拷贝jar包，而且arthas会拖慢应用本身，如果条件不允许，又该如何诊断呢？这边简单介绍下jdk自带的命令行工具。

六、JVM问题定位命令

在 JDK 安装目录的 bin 目录下默认提供了很多有价值的命令行工具。每个小工具体积基本都比较小，因为这些工具只是 jdk\lib\tools.jar 的简单封装。

其中，定位排查问题时最为常用命令包括：jps（进程）、jmap（内存）、jstack（线程）、jinfo（参数）等。

• jps：查询当前机器所有Java进程信息
• jmap：输出某个 Java 进程内存情况
• jstack：打印某个 Java 线程的线程栈信息
• jinfo：用于查看 jvm 的配置参数

6.1 jps

jps 用于输出当前用户启动的所有进程 ID，当线上发现故障或者问题时，利用 jps 快速定位对应的 Java 进程 ID。

jps -m

参数解释：

-m：输出传入 main 方法的参数

-l：输出完全的包名，应用主类名，jar的完全路径名

当然，我们也可以使用 Linux 提供的查询进程状态命令也能快速获取 Tomcat 服务的进程 id。比如：

ps -ef | grep tomcat

6.2 jmap

jmap（Java Memory Map）可以输出所有内存中对象的工具，甚至可以将 VM 中的 heap，以二进制输出成文本，使用方式如下：
jmap -heap：

jmap -heap pid   输出当前进程JVM堆内存新生代、老年代、持久代、GC算法等信息

**注意：**pid 通过jps命令得知

jmap -histo：

jmap -histo:live pid | head -n 20  输出当前进程内存中所有对象包含的大小

输出当前进程内存中所有对象实例数（instances）和大小（bytes），如果某个业务对象实例数和大小存在异常情况，可能存在内存泄露或者业务设计方面存在不合理之处。

jmap -dump：

jmap -dump:format=b,file=/apps/logs/gc/dump.hprof {pid} 
以二进制形式输出当前内存的堆情况，便于导入MAT等工具进行分析情况

一般我们要求给 JVM 添加参数 -XX:+Heap Dump On Out Of Memory Error OOM 确保应用发生 OOM 时 JVM 能够保存并 dump 出当前的内存镜像。当然如果你决定手动 dump 内存时，dump 操作占据一定 CPU 时间片、内存资源、磁盘资源等，因此会带来一定的负面影响。

此外，dump 的文件可能比较大,一般我们可以考虑使用zip命令对文件进行压缩处理，这样在下载文件时能减少带宽的开销。在下载 dump 文件完成之后，由于 dump 文件较大可将 dump 文件备份至制定位置或者直接删除，以释放磁盘在这块的空间占用。

6.3 jstack

jstack用于打印某个 Java 线程的线程栈信息，通常用以下三步分析：

printf '%x\n' tid    10进制至16进制线程转换
jstack pid | grep tid -C 30 --color   
ps -mp 8278 -o THREAD,tid,time | head -n 40

举个栗子，某 Java 进程 CPU 占用率高，我们想要定位到其中 CPU 占用率最高的线程，如何定位？

1、利用 top 命令可以查出占 CPU 最高的线程 pid

top -Hp pid

2、 占用率最高的线程 ID 为 22021，将其转换为16进制形式（因为 java native 线程以16进制形式输出）

printf '%x\n' 22021

3、 利用 jstack 打印出 Java 线程调用栈信息

jstack 21993 | grep '0x5605' -A 50 --color

6.4 jinfo

jinfo可以用来查看正在运行的 java 应用程序的扩展参数，包括Java System属性和JVM命令行参数；也可以动态的修改正在运行的 JVM 一些参数。

jinfo pid

6.5 jstat

jstat命令可以查看堆内存各部分的使用量，以及加载类的数量。

jstat -gc pid

6.6 内存分析工具

6.6.1 MAT

MAT（Memory Analyzer Tool），一个基于 Eclipse 的内存分析工具，是一个快速、功能丰富的 JAVA heap 分析工具，它可以帮助我们查找内存泄漏和减少内存消耗。使用内存分析工具从众多的对象中进行分析，快速的计算出在内存中对象的占用大小，看看是谁阻止了垃圾收集器的回收工作，并可以通过报表直观的查看到可能造成这种结果的对象。

右侧的饼图显示当前快照中最大的对象。单击工具栏上的柱状图，可以查看当前堆的类信息，包括类的对象数量、浅堆（Shallow heap）、深堆（Retained Heap）。

浅堆表示一个对象结构所占用内存的大小。深堆表示一个对象被回收后，可以真实释放的内存大小。

• 支配树（The Dominator Tree）：

  列出了堆中最大的对象，第二层级的节点表示当被第一层级的节点所引用到的对象，当第一层级对象被回收时，这些对象也将被回收。这个工具可以帮助我们定位对象间的引用情况，垃圾回收时候的引用依赖关系

• Path to GC Roots

  被JVM持有的对象，如当前运行的线程对象，被systemclass loader加载的对象被称为GC Roots， 从一个对象到GC Roots的引用链被称为Path to GC Roots， 通过分析Path to GC Roots可以找出JAVA的内存泄露问题，当程序不在访问该对象时仍存在到该对象的引用路径。

6.6.2 Perfma社区工具

Perfma是寒泉子（你假笨）创立的专注于JVM性能方向的技术公司，在Perfma社区中提供了一款XSheepdog的Java线程dump分析工具，它支持本地、HTTP、FTP三种形式的dump文件上传方式，这里也对其不做过多介绍，大家可以自己上去玩一玩《Perfma社区》，顺手记录一张之前分析的结果图：

七、GC分析

7.1 GC 日志分析

7.1.1 GC 日志详细分析

Java 虚拟机GC日志是用于定位问题重要的日志信息，频繁的GC将导致应用吞吐量下降、STW时间增加，严重情况下甚至导致服务的不可用。

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/apps/logs/gc/gc.log -XX:+UseConcMarkSweepGC

我们可以在 Java 应用的启动参数中增加**-XX:+PrintGC -XX:+PrintGCDetails**输出 GC 的详细日志，另外还可以增加其他的辅助参数，如 -Xloggc 指定 GC 日志文件地址。如果你的应用还没有开启该参数，下次重启时可以考虑增加这些参数。

上图为线上某应用在平稳运行状态下的GC日志截图。

2017-12-29T18:25:22.753+0800: 73143.256: [GC2017-12-29T18:25:22.753+0800: 73143.257: [ParNew: 559782K->1000K(629120K), 0.0135760 secs] 825452K->266673K(2027264K), 0.0140300 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

# 解释说明
[2017-12-29T18:25:22.753+0800: 73143.256]： 自JVM启动73143.256秒时发生本次GC.
[ParNew: 559782K->1000K(629120K), 0.0135760 secs]： 对新生代进行的GC，使用ParNew收集器，559782K是新生代回收前的大小,1000K是新生代回收后大小,629120K是当前新生代分配的内存总大小, 0.0135760 secs表示本次新生代回收耗时 0.0135760秒
[825452K->266673K(2027264K), 0.0140300 secs]：825452K是回收堆内存大小,266673K是回收堆之后内存大小，2027264K是当前堆内存总大小,0.0140300 secs表示本次回收共耗时0.0140300秒
[Times: user=0.02 sys=0.00, real=0.02 secs]： 用户态耗时0.02秒,系统态耗时0.00,实际耗时0.02秒

无论是 minor GC 或者是 Full GC，我们主要关注 GC 回收实时耗时， 如 real=0.02secs，即 stop the world 时间，如果该时间过长，则严重影响应用性能。

7.1.2 CMS GC 日志分析

Concurrent Mark Sweep（CMS）是老年代垃圾收集器，从名字（Mark Sweep）可以看出，CMS 收集器就是“标记-清除”算法实现的，分为六个步骤：

• 初始标记（STW initial mark）
• 并发标记（Concurrent marking）
• 并发预清理（Concurrent precleaning）
• 重新标记（STW remark）
• 并发清理（Concurrent sweeping）
• 并发重置（Concurrent reset）

其中初始标记（STW initial mark） 和 重新标记（STW remark）需要“Stop the World”。

初始标记 ：在这个阶段，需要虚拟机停顿正在执行的任务，官方的叫法 STW（Stop The Word）。这个过程从垃圾回收的"根对象"开始，只扫描到能够和"根对象"直接关联的对象，并作标记。所以这个过程虽然暂停了整个 JVM，但是很快就完成了。

并发标记 ：这个阶段紧随初始标记阶段，在初始标记的基础上继续向下追溯标记。并发标记阶段，应用程序的线程和并发标记的线程并发执行，所以用户不会感受到停顿。

并发预清理 ：并发预清理阶段仍然是并发的。在这个阶段，虚拟机查找在执行并发标记阶段新进入老年代的对象（可能会有一些对象从新生代晋升到老年代， 或者有一些对象被分配到老年代）。通过重新扫描，减少下一个阶段"重新标记"的工作，因为下一个阶段会 Stop The World。

重新标记 ：这个阶段会暂停虚拟机，收集器线程扫描在 CMS 堆中剩余的对象。扫描从"跟对象"开始向下追溯，并处理对象关联。

并发清理 ：清理垃圾对象，这个阶段收集器线程和应用程序线程并发执行。

并发重置 ：这个阶段，重置 CMS 收集器的数据结构，等待下一次垃圾回收。

CMS 使得在整个收集的过程中只是很短的暂停应用的执行，可通过在 JVM 参数中设置 -XX:UseConcMarkSweepGC 来使用此收集器，不过此收集器仅用于 old 和 Perm（永生）的对象收集。CMS 减少了 stop the world 的次数，不可避免地让整体 GC 的时间拉长了。

Full GC 的次数说的是 stop the world 的次数，所以一次 CMS 至少会让 Full GC 的次数+2，因为 CMS Initial mark 和 remark 都会 stop the world，记做2次。而 CMS 可能失败再引发一次 Full GC。

上图为线上某应用在进行 CMS GC 状态下的 GC 日志截图。

2017-11-02T09:27:03.989+0800: 558115.552: [GC [1 CMS-initial-mark: 1774783K(1926784K)] 1799438K(2068800K), 0.0123430 secs] [Times: user=0.01 sys=0.01, real=0.02 secs] 
2017-11-02T09:27:04.001+0800: 558115.565: [CMS-concurrent-mark-start]
2017-11-02T09:27:04.714+0800: 558116.277: [CMS-concurrent-mark: 0.713/0.713 secs] [Times: user=1.02 sys=0.03, real=0.71 secs] 
2017-11-02T09:27:04.714+0800: 558116.277: [CMS-concurrent-preclean-start]
2017-11-02T09:27:04.722+0800: 558116.285: [CMS-concurrent-preclean: 0.008/0.008 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2017-11-02T09:27:04.722+0800: 558116.286: [CMS-concurrent-abortable-preclean-start]
2017-11-02T09:27:04.836+0800: 558116.399: [GC2017-11-02T09:27:04.836+0800: 558116.400: [ParNew: 138301K->6543K(142016K), 0.0155540 secs] 1913085K->1781327K(2068800K), 0.0160610 secs] [Times: user=0.03 sys=0.01, real=0.02 secs] 
2017-11-02T09:27:05.005+0800: 558116.569: [CMS-concurrent-abortable-preclean: 0.164/0.283 secs] [Times: user=0.46 sys=0.02, real=0.28 secs] 
2017-11-02T09:27:05.006+0800: 558116.570: [GC[YG occupancy: 72266 K (142016 K)]2017-11-02T09:27:05.006+0800: 558116.570: [Rescan (parallel) , 0.2523940 secs]2017-11-02T09:27:05.259+0800: 558116.822: [weak refs processing, 0.0011240 secs]2017-11-02T09:27:05.260+0800: 558116.823: [scrub string table, 0.0028570 secs] [1 CMS-remark: 1774783K(1926784K)] 1847049K(2068800K), 0.2566410 secs] [Times: user=0.14 sys=0.00, real=0.26 secs] 
2017-11-02T09:27:05.265+0800: 558116.829: [CMS-concurrent-sweep-start]
2017-11-02T09:27:05.422+0800: 558116.986: [GC2017-11-02T09:27:05.423+0800: 558116.986: [ParNew: 120207K->2740K(142016K), 0.0179330 secs] 1885446K->1767979K(2068800K), 0.0183340 secs] [Times: user=0.03 sys=0.01, real=0.02 secs] 
2017-11-02T09:27:06.240+0800: 558117.804: [GC2017-11-02T09:27:06.240+0800: 558117.804: [ParNew: 116404K->3657K(142016K), 0.0134680 secs] 1286444K->1173697K(2068800K), 0.0138460 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2017-11-02T09:27:06.966+0800: 558118.530: [GC2017-11-02T09:27:06.966+0800: 558118.530: [ParNew: 117321K->2242K(142016K), 0.0135210 secs] 738838K->623759K(2068800K), 0.0140130 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2017-11-02T09:27:07.144+0800: 558118.708: [CMS-concurrent-sweep: 1.820/1.879 secs] [Times: user=2.88 sys=0.14, real=1.88 secs] 
2017-11-02T09:27:07.144+0800: 558118.708: [CMS-concurrent-reset-start]
2017-11-02T09:27:07.149+0800: 558118.713: [CMS-concurrent-reset: 0.005/0.005 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

如果你已掌握 CMS 的垃圾收集过程，那么上面的 GC 日志你应该很容易就能看的懂，这里我就不详细展开解释说明了。

此外 CMS 进行垃圾回收时也有可能会发生失败的情况。

异常情况有：

伴随 prommotion failed，然后 Full GC：

[prommotion failed：存活区内存不足，对象进入老年代，而此时老年代也仍然没有内存容纳对象，将导致一次Full GC]

伴随 concurrent mode failed，然后 Full GC：

[concurrent mode failed：CMS回收速度慢，CMS完成前，老年代已被占满，将导致一次Full GC]

频繁 CMS GC：

[内存吃紧，老年代长时间处于较满的状态，可以适当的增大堆内存]

八、常见问题分析、解答

**问：**生产环境里某个节点里的容器里面服务挂了，但是在预生产环境无法重现，而生产环境监控里面显示 cpu、内存、堆栈都正常。而那个节点重启之后就正常，但是过段时间又出现问题。这种情况有什么好的方法排查问题？

**答：**这种情况首先需要排查内核版本，排查Tomcat版本，可能自身应用存在 bug，真的没办法可以考虑降低日志等级，打印出更为详细有价值的启动/业务日志信息。

---

问：线上排查问题 dump 或 jstack 导出文件分析经常无响应导致无法导出查看内存问题和线程问题，有什么办法吗？

答： 增加 -F 强制，在 jmap-dump 使用，如果 pid 没有相应的回复。当然 -F 也可能没办法 dump 下来，那就只能去分析日志了。当然如果你决定手动 dump 内存时，dump 操作占据一定 CPU 时间片、内存资源、磁盘资源等，对系统的正常的运行可能会有一些影响。

九、案例分析

某工程消费ActiveMQ消息，该工程整合了Apache Camel，经过运维排查定位到Camel拉取到了消息，但收到消息后打印日志时却延迟了十几分钟，Camel配置了MySQL用于校验幂等，一些列初步排查下来，未找到原因，该如何排查？

线上问题出错，而且只有线上环境能复现问题，在运维人员同意的情况下，将Alibaba Arthas拷贝进容器中，启动Arthas，开始跟踪，由于是SpringBoot工程，并且Camel作为消息入口，故先从配置开始跟踪，详细排查问题如下：

1、延迟场景，首先排查有无死锁产生

thread -b

仔细分析下来并不是死锁，那就从入口开始。

2、从Camel配置开始跟踪

trace --skipJDKMethod true org.apache.camel.builder.RouteBuilder configure '#cost > 20' -n 10

**注意：**skipJDKMethod：跟踪结果不包含JDK方法。

开始构造延迟场景，但未能跟踪到相关信息。

于是调整策略，从消息派发器开始跟踪。

3、跟踪统一消息派发器MessageDispatcher

trace com.test.messagedispatcher.MessageDispatcher onMessage -n 10

开始构造延迟场景，也没能跟踪到与延迟相关的信息，继续调整方向，下载了Apache Camel源代码，开始分析从JMS 消费者开始分析Camel核心入口方法，定位到创建监听器代码：

protected void createMessageListener(JmsEndpoint endpoint, Processor processor) {
        messageListener = new EndpointMessageListener(endpoint, processor);
        getEndpoint().getConfiguration().configureMessageListener(messageListener);
        messageListener.setBinding(endpoint.getBinding());
        messageListener.setAsync(endpoint.getConfiguration().isAsyncConsumer());
}

4、分析Camel创建监听器方法

trace org.apache.camel.component.jms.EndpointMessageListener *

继续构造延迟场景，结果如下：

上图红色部分出现了930027ms，初步定位到了延迟发生在Camel中间件，继续跟踪

5、跟踪AsyncProcessor:process方法

trace org.apache.camel.AsyncProcessor process

继续构造延迟场景，跟踪结果如下、

原来是幂等消费阻塞了几分钟，最后的关键信息是，继续跟踪。

6、跟踪IdempotentRepository:add方法

trace org.apache.camel.spi.IdempotentRepository add

原来是数据库事务的问题，继续跟踪。

7、直至定位到原因

原来是抓取JDBC连接的时候阻塞了。