Java常⻅线上故障排查⽅案

Java常⻅线上故障排查⽅案
⼀、前⾔
⼆、Java常⻅线上问题总结
三、如何定位问题
3.1、业务⽇志分析排查
3.2、APM分析排查
3.3、物理环境排查
3.3.1 CPU分析
3.3.2 内存分析
3.3.3 磁盘分析
3.3.4 ⽹络分析
3.4、应⽤服务排查
3.4.1 CPU分析
3.4.2 内存分析
3.5、云⼚商或运营商问题排查
四、常⽤Linux分析命令
4.1 CPU
4.2 内存
4.3 磁盘
4.4 ⽹络
五、Arthas诊断命令
5.1 下载安装
5.2 启动Arthas
5.3 开始诊断
5.4 查看dashboard
5.5 arthas常⻅命令介绍
六、JVM问题定位命令
6.1 jps
6.2 jmap
6.3 jstack
6.4 jinfo
6.5 jstat
6.6 内存分析⼯具 MAT
6.6.1 什么是 MAT
七、GC分析
7.1 GC ⽇志分析
7.1.1 GC ⽇志详细分析
7.1.2 CMS GC ⽇志分析
⼋、常⻅问题分析、解答
九、案例分析
1、延迟场景，⾸先排查有⽆死锁产⽣
2、从Camel配置开始跟踪
3、跟踪统⼀消息派发器MessageDispatcher
4、分析Camel创建监听器⽅法
5、跟踪AsyncProcessor:process⽅法
6、跟踪IdempotentRepository:add⽅法
7、直⾄定位到原因
⼀、前⾔
在软件开发过程中，排查和修复产线问题是每⼀位⼯程师都需要掌握的基本技能。但是在⽣产环境中，
程序代码、硬件、⽹络、协作软件等任⼀因素，都会引发意想不到的问题，所以排查产线问题⽐较困
难，所以问题的定位体现了⼀名⼯程师的基础能⼒，问题的解决则体现了⼯程师的技能素养。
以下从5个⽅⾯分享产线常⻅问题的排查⼿段。
1. Java常⻅线上问题总结
2. 如何定位问题
3. APM链路跟踪分析
4. 常⽤Linux分析命令
5. Arthas（阿尔萨斯）诊断命令
6. JVM问题定位命令
7. GC分析
⼆、Java常⻅线上问题总结
绝⼤多数Java线上问题从表象来看通常可以归纳为4个⽅⾯：CPU、内存、磁盘、⽹络。⽐如，应⽤上线
后突然CPU使⽤率99%、内存泄漏、STW时间过⻓，这些问题通常可以分为两⼤类：
系统异常 （CPU占⽤率过⾼、磁盘使⽤率100%、系统可⽤内存低等）
业务异常 （服务运⾏⼀段时间⾃动退出、服务间调⽤时间过⻓、多线程并发异常、死锁等）
三、如何定位问题
解决问题的第⼀步是定位问题，因为只有定位到了问题产⽣的原因，才能准确的抉择出解决⽅案，排查
⼿段⼀般包括以下⼏项，也可以将此理解为排查顺序：
1. 业务⽇志分析排查
2. APM分析排查
3. 外部环境排查
4. 应⽤服务排查
5. 云⼚商或运营商问题排查
3.1、业务⽇志分析排查
通常情况下，⼤部分错误信息都会在⽇志上有所体现，⽐如看看下⾯这段代码：
这段代码使⽤了并发流将数据加⼊到⼀个List中，再运⾏过程中，抛出了
ArrayIndexOutOfBoundsException ，具体异常栈信息如下：
通过⽇志可以看到出错的位置在TaskServiceImpl.java ⽂件的第75⾏代码上，错误信息
是java.lang.ArrayIndexOutOfBoundsException:163 ，这就是问题定位，整体描述出来就是： 在
TaskServiceImpl.java⽂件中第75⾏代码上出现了数组越界异常，引起异常的原因是在调⽤
java.util.ArrayList#add()⽅法时因为并发请求导致没有动态扩展数组容量。
为什么我们能够直接描述出来是在调⽤ArrayList#add() ⽅法时因为并发请求导致的没有动态扩展数
组容量呢？因为我们结合ArrayList的内部实现原理及动态扩容的特性，可以知道在单线程的情况下，代
码是串⾏执⾏，ArrayList内的数组都会是先扩容再插⼊，所以不会出现数组越界的错误，既然单线程不
会引起该错误，那⼀定就是多线程并发造成的了，解决⽅案就是给代码加锁或者由并发改串⾏，就是这
么简单，这就是技能素养的体现。
通过上⾯的分析，教育了我们：⼀定要在关键代码逻辑位置输出相关⽇志，尤其是在代码发⽣异常的时
候，定要将⽇志输出到⽂件中，只有这样，才更利于我们的排查。
3.2、APM分析排查
APM，全称Application Performance Management，应⽤性能管理，⽬的是通过各种探针采集数据，
收集关键指标，同时搭配数据呈现以实现对应⽤程序性能管理和故障管理的系统化解决⽅案。通过分布
式链路调⽤跟踪系统，通过在系统请求中透传 trace-id，将所有相关⽇志进⾏聚合，然后⽇志统⼀采集
和分析后，以图形化的形式展示给⼯程师们，⽽他们在排查问题的时候，可以简单粗暴且直观的调度出
问题最根本的原因。
业务⽇志较优于解决单体服务异常，但现在的应⽤通常使⽤的是分布式架构，⽽在分布式系统中，仅通
过单服务节点的⽇志，很难将错误信息与请求链路关联在⼀起，也就是通过系统中某个服务的异常⽇志
信息很难定位到问题的根本原因。并且我们还需要关注各服务执⾏过程中的耗时情况，及时的发现异常
服务，并根据异常信息进⾏修复。要满⾜这种需求，仅通过分析单个服务的⽇志信息是不够的，此时则
需要APM进⾏全链路分析，通过请求链路监控，实时的发现链路中相关服务的异常情况。
业务流程图
实现架构图
⽐如我们使⽤Skywalking，进⼊到Skywalking的控制台查看的链路信息就是这样的：
⽬前市场上使⽤较多的链路跟踪⼯具有如下⼏个：
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/referenc
e/html/#sending-spans-to-zipkin
3.3、物理环境排查
物理环境是指⼯程所依附的物理环境，⽐如服务器、宿主机、容器等，细分为服务器负载、CPU、内
存、磁盘、⽹络⼏个⽅⾯。
3.3.1 CPU分析
排查CPU的⽬的主要是查看服务器CPU的使⽤率， 使⽤top命令分析CPU使⽤情况
3.3.2 内存分析
使⽤free -m命令查看内存使⽤情况
3.3.3 磁盘分析
使⽤df -h、iostat、lsof等命令查看磁盘IO情况，找到读写异常的进程
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 磁盘
磁盘满了很多时候会引发系统服务不可⽤等问题
4.4 ⽹络
dstat 是⼀个可以取代vmstat，iostat，netstat和ifstat这些命令的多功能产品。
df -h
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 下载安装
5.2 启动Arthas
arthas 会列出已存在的Java进程，并提醒输⼊序号，键⼊回⻋，进⼊arthas 诊断界⾯。
5.3 开始诊断
按照提醒，这⾥输⼊需要诊断的序号，输⼊回⻋，响应界⾯如下：
curl -O https://alibaba.github.io/arthas/arthas-boot.jar
java -jar arthas-boot.jar
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.ht
ml。
arthas使⽤上相对JVM命令简单很多，即便是⼯作年限不多的苏研⼩伙伴学起来也很快。熟练使⽤
arthas应该能诊断出⼤部分线上应⽤问题，但⽣产环境通常不允许擅⾃拷⻉jar包，⽽且arthas会拖慢应
⽤本身，如果条件不允许，⼜该如何诊断呢？这边简单介绍下jdk⾃带的命令⾏⼯具。
六、JVM问题定位命令
在 JDK 安装⽬录的 bin ⽬录下默认提供了很多有价值的命令⾏⼯具。每个⼩⼯具体积基本都⽐较⼩，因
为这些⼯具只是 jdklib ools.jar 的简单封装。
其中，定位排查问题时最为常⽤命令包括：jps（进程）、jmap（内存）、jstack（线程）、jinfo（参
数）等。
jps：查询当前机器所有Java进程信息
jmap：输出某个 Java 进程内存情况
jstack：打印某个 Java 线程的线程栈信息
jinfo：⽤于查看 jvm 的配置参数
6.1 jps
jps ⽤于输出当前⽤户启动的所有进程 ID，当线上发现故障或者问题时，利⽤ jps 快速定位对应的 Java
进程 ID。
参数解释：
-m：输出传⼊ main ⽅法的参数
-l：输出完全的包名，应⽤主类名，jar的完全路径名
jps -m
当然，我们也可以使⽤ Linux 提供的查询进程状态命令也能快速获取 Tomcat 服务的进程 id。⽐如：
6.2 jmap
jmap（Java Memory Map）可以输出所有内存中对象的⼯具，甚⾄可以将 VM 中的 heap，以⼆进制输
出成⽂本，使⽤⽅式如下： jmap -heap：
注意：pid 通过jps命令得知
ps -ef | grep tomcat
jmap -heap pid 输出当前进程JVM堆内存新⽣代、⽼年代、持久代、GC算法等信息
jmap -histo：
jmap -histo:live pid | head -n 20 输出当前进程内存中所有对象包含的⼤⼩
输出当前进程内存中所有对象实例数（instances）和⼤⼩（bytes），如果某个业务对象实例数和⼤⼩
存在异常情况，可能存在内存泄露或者业务设计⽅⾯存在不合理之处。
jmap -dump：
⼀般我们要求给 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 线程的线程栈信息，通常⽤以下三步分析：
举个栗⼦，某 Java 进程 CPU 占⽤率⾼，我们想要定位到其中 CPU 占⽤率最⾼的线程，如何定位？
1、利⽤ top 命令可以查出占 CPU 最⾼的线程 pid
jmap -dump:format=b,file=/apps/logs/gc/dump.hprof {pid}
以⼆进制形式输出当前内存的堆情况，便于导⼊MAT等⼯具进⾏分析情况
printf '%x ' tid 10进制⾄16进制线程转换
jstack pid | grep tid -C 30 --color
ps -mp 8278 -o THREAD,tid,time | head -n 40
top -Hp pid
2、 占⽤率最⾼的线程 ID 为 22021，将其转换为16进制形式（因为 java native 线程以16进制形式输
出）
3、 利⽤ jstack 打印出 Java 线程调⽤栈信息
printf '%x ' 22021
jstack 21993 | grep '0x5605' -A 50 --color
6.4 jinfo
jinfo可以⽤来查看正在运⾏的 java 应⽤程序的扩展参数，包括Java System属性和JVM命令⾏参数；也
可以动态的修改正在运⾏的 JVM ⼀些参数。
6.5 jstat
jstat命令可以查看堆内存各部分的使⽤量，以及加载类的数量。
jinfo pid
jstat -gc pid
6.6 内存分析⼯具 MAT
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的内存泄露问题，当程序不在访问该对象时仍存在到该对象的引⽤路径。
七、GC分析
七、GC分析
7.1 GC ⽇志分析
7.1.1 GC ⽇志详细分析
Java 虚拟机GC⽇志是⽤于定位问题重要的⽇志信息，频繁的GC将导致应⽤吞吐量下降、响应时间增
加，甚⾄导致服务不可⽤。
我们可以在 Java 应⽤的启动参数中增加-XX:+PrintGCDetails 可以输出 GC 的详细⽇志，例外还可以增
加其他的辅助参数，如 -Xloggc 制定 GC ⽇志⽂件地址。如果你的应⽤还没有开启该参数,下次重启时请
加⼊该参数。
上图为线上某应⽤在平稳运⾏状态下的GC⽇志截图。
⽆论是 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”。
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/apps/logs/gc/gc.log -
XX:+UseConcMarkSweepGC
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秒
初始标记 ：在这个阶段，需要虚拟机停顿正在执⾏的任务，官⽅的叫法 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-precleanstart]
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]
如果你已掌握 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 导出⽂件分析经常⽆响应导致⽆法导出查看内存问题和线程问题，有
什么办法吗？
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]
答： 增加 -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配置开始跟踪
注意：skipJDKMethod：跟踪结果不包含JDK⽅法。
开始构造延迟场景，但未能跟踪到相关信息。
于是调整策略，从消息派发器开始跟踪。
trace --skipJDKMethod true org.apache.camel.builder.RouteBuilder configure
'#cost > 20' -n 10
3、跟踪统⼀消息派发器MessageDispatcher
开始构造延迟场景，也没能跟踪到与延迟相关的信息，继续调整⽅向，下载了Apache Camel源代码，开
始分析从JMS 消费者开始分析Camel核⼼⼊⼝⽅法，定位到创建监听器代码：
4、分析Camel创建监听器⽅法
继续构造延迟场景，结果如下：
上图红⾊部分出现了930027ms，初步定位到了延迟发⽣在Camel中间件，继续跟踪
5、跟踪AsyncProcessor:process⽅法
继续构造延迟场景，跟踪结果如下、
trace com.test.messagedispatcher.MessageDispatcher onMessage -n 10
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());
}
trace org.apache.camel.component.jms.EndpointMessageListener *
trace org.apache.camel.AsyncProcessor process
原来是幂等消费阻塞了⼏分钟，最后的关键信息是，继续跟踪。
6、跟踪IdempotentRepository:add⽅法
原来是数据库事务的问题，继续跟踪。
7、直⾄定位到原因
原来是抓取JDBC连接的时候阻塞了
trace org.apache.camel.spi.IdempotentRepository add