1. 一次凌晨告警引发的动手:高CPU问题的常见剧本与误判陷阱
如果你维护过ActiveMQ broker,大概率遇到过这样一个场景:凌晨三点,监控平台突然发来告警,broker所在机器的CPU使用率冲到了百分之九十几,甚至在持续运行几个小时后开始出现消费者超时、生产者发送缓慢、管理控制台打不开的状态。我最初碰到这类问题时,第一反应是登录机器看进程、敲jstack、看一眼日志,然后陷入越看越乱的局面。
这类问题最麻烦的地方在于:高CPU本身只是一个结果,触发它的原因却可能藏在好几个层面。按我这些年踩过的坑,最常见的“剧本”大概有这几类。
第一类是业务处理线程陷入死循环或阻塞轮询。某个消费者在处理消息时,因为数据边界条件没处理好,进入了明显的忙循环,或者是一个while循环里缺少有效的wait/sleep,导致CPU被一个线程吃满。这种情况下jstack里会出现大量同一栈帧的“RUNNABLE”状态线程。
第二类是消息积压带来的连锁反应。broker收到大量消息,持久化存储的写盘任务、索引更新任务、日志追加任务同时活跃,再加上消费者不断拉取,整个处理链路全部处于高负载状态。这种情况CPU高是“表”,真正的里子是存储和分发压力上来后,线程池调度变得异常激进。
第三类是GC频繁且回收效率低。ActiveMQ的broker本质是Java进程,如果堆内存配置不合理,或者消息体本身设计得过大,会产生大量临时对象。当GC线程几乎不间断地Full GC,CPU自然被顶上去,而业务线程反而大量处于阻塞等待状态。
第四类是连接数异常膨胀。某些客户端在断线重连逻辑上写得比较“暴力”,或者生产端出现大批量短连接创建,broker的传输线程、会话线程、心跳检测线程都会跟着忙起来。
我最初犯的误判就是把所有精力放在“看线程”上,却忽略了线程样本之间的时序关系。单次jstack只能告诉你此刻有哪些线程在跑,无法告诉你CPU高是因为某几个线程持续燃烧,还是大量线程轮流抖动。后来我把思路调整成“用连续多次采样建立线程状态的时间序列”,再结合队列深度和GC日志一起看,问题才变得清晰起来。也就是从那个时候开始,我动手写了这个ActiveMQ高CPU问题诊断脚本,把整个排查过程固化成一套半自动化的采集工具。
2. 诊断脚本的整体设计:采集哪些信息才真正有用
写脚本之前,我先梳理了排查高CPU问题的信息需求。只说“采集jstack”是不够的,必须同时把线程栈、运行队列、JVM内存状况、GC日志、broker的队列统计和连接统计放在一张时间轴上,才能还原故障现场。
我最终把这套脚本设计成四个采集模块:连续线程栈采样、线程状态聚合统计、broker队列与连接统计、JVM与GC快照。脚本运行时会把所有输出打成带时间戳的目录,便于事后按时间线复盘。
2.1 为什么jstack要连续采样,而不是采集一次
这是整个诊断的关键。单次jstack的误判率相当高。比如你正好在某个瞬间抓到某个线程处于“WAITING”状态,就很容易得出“线程都在等待,CPU高是GC造成的”这类结论;但连续采样几个回合之后,你才会发现那些“WAITING”线程其实在极短时间内频繁被唤醒,整体消耗的CPU相当可观。
我在脚本里设置的默认策略是:每隔5秒采样一次,整个采样周期撑到30秒以上。如果CPU已经高到接近100%,采样间隔可以缩短到2到3秒,但要注意jstack触发线程栈抓取的过程本身会对JVM施加短暂的额外负载。我在一次事故中用1秒间隔连续采样了20次,结果broker在采样期间出现了一次明显停顿。后来我把默认间隔固定在5秒,异常情况下使用3秒,整体采样次数控制在10到15次以内。
每个采样周期生成的线程快照文件,脚本会在最后统一解析并追加到一个全量汇总文件里。这个汇总文件才是后续分析的源头,而不是某个孤立的单次快照。
2.2 队列统计和消费者状态:CPU之外的另一只眼睛
线程栈只能说明“CPU被谁吃了”,不能说明“为什么它要把CPU吃满”。所以我在脚本里加了两个数据源:一个是ActiveMQ的JMX统计,另一个是broker日志里的相关线索。
JMX这块,我通过JDK自带的jcmd或者直接调用JMX接口获取以下指标:
- 每个队列的当前深度EnqueueCount和DequeueCount,用于判断消息是流入大于流出还是刚好持平;
- 消费者数量、消费者是否处于活跃状态;
- 内存存储和磁盘存储的使用量;
- Broker的连接总数和每秒新建连接数。
这些指标和jstack对照起来,才会有真正的诊断价值。比如说,线程栈里看到大量“调度线程”处于RUNNABLE,同时队列深度持续不降,那基本可以确定是消费端能力不足,broker在拼命分发消息但下游消化不掉。反过来,如果队列深度很低、发消息也很顺畅,但CPU依然高,那问题大概率不在broker的消息分发路径上,而在业务逻辑的某些异常循环里。
2.3 脚本结构的取舍
我没有把这个脚本设计成一个“大而全”的自动化分析工具,而是把它定位成“现场取证工具”。理由是生产事故发生时,最重要的是在尽量短的时间内把现场数据留下来。分析可以事后慢慢做,但现场一旦被重启、被恢复、被水平扩容干扰,很多证据就永远消失了。
所以脚本的默认模式下,只做采集和初步汇总,不做自动判定。每一个采集目录里都能看到独立文件,方便把这些文件打包交给同事或者在本地慢慢分析。脚本的初始化阶段会确认Java进程的PID,如果没有传PID参数,就尝试从进程列表中匹配ActiveMQ的启动类。
3. 脚本核心实现:高频采样线程栈,自动排序异常线程
这个脚本主体是Bash写的,有个辅助的小工具用于解析线程状态。下面是脚本的核心框架,我先把主流程贴出来。
#!/bin/bash # ActiveMQ高CPU诊断脚本 - 现场取证模式 # 用法: ./amq_cpu_diag.sh <PID> [采样间隔(秒)] [采样次数] PID=$1 INTERVAL=${2:-5} COUNT=${3:-12} OUT_DIR="amq_cpu_diag_$(date +%Y%m%d_%H%M%S)" mkdir -p "$OUT_DIR" echo "[$(date '+%Y-%m-%d %H:%M:%S')] 开始采集 ActiveMQ($PID) 线程与JVM数据" echo "采样间隔: ${INTERVAL}s, 采样次数: ${COUNT}" for ((i=1; i<=COUNT; i++)); do echo "[$(date '+%Y-%m-%d %H:%M:%S')] 第 $i 次采样..." # 1. 线程栈快照 jstack "$PID" > "$OUT_DIR/jstack_$i.txt" 2>&1 # 2. 线程状态聚合统计 awk -v round="$i" '/^"/{ if (match($0, /(RUNNABLE|WAITING|TIMED_WAITING|BLOCKED)/)) { state=substr($0, RSTART, RLENGTH); count[state]++ }} END { print "=== Round " round " 线程状态统计 ==="; for (s in count) print s, count[s]; }' "$OUT_DIR/jstack_$i.txt" > "$OUT_DIR/thread_state_$i.txt" # 3. GC与堆概况 jstat -gcutil "$PID" 1000 1 | tail -1 > "$OUT_DIR/gc_util_$i.txt" sleep "$INTERVAL" done # 全量线程栈汇总文件:方便事后搜索 cat "$OUT_DIR"/jstack_*.txt > "$OUT_DIR/all_jstack_merged.txt" # 输出初步统计 echo "[$(date '+%Y-%m-%d %H:%M:%S')] 采集完成,结果目录: $OUT_DIR"3.1 主流程与PID获取
脚本一开始接收三个参数:PID、采样间隔和采样次数。生产环境中最常见的问题是PID怎么拿。ActiveMQ的进程一般可以通过ps -ef | grep activemq找到,但有些环境里同一个机器上有多个Java进程,必须用jps -l或者看启动参数里的-Dactivemq.home来区分。
我给脚本加了自动识别的逻辑:
if [ -z "$PID" ]; then PID=$(ps -ef | grep '[o]rg.apache.activemq' | grep -v grep | awk '{print $2}' | head -1) if [ -z "$PID" ]; then PID=$(jps -l | grep '[a]ctivemq' | awk '{print $1}') fi fi if [ -z "$PID" ]; then echo "无法自动识别ActiveMQ进程PID,请手动指定: $0 <PID>" exit 1 fi这里有个小坑:某些机器上jstack命令不在root用户的PATH里。脚本里最好是先用which jstack找一次,找不到就尝试常见的JDK路径,否则后续循环跑起来会一直报“command not found”,白白浪费采集窗口。
3.2 连续jstack采样与线程状态归类
jstack输出中,每个线程有一段固定的头部格式,比如"ActiveMQ Broker" #96 daemon prio=5 os_prio=0 cpu=1234.56ms elapsed=12345.67s tid=0x... nid=0x... runnable [0x...],紧接着是栈帧。线程状态一般体现在栈帧之前的java.lang.Thread.State: RUNNABLE这一行。
脚本里的awk解析,就是抓取Thread.State后面的状态值,按轮次统计。你可能会发现,不同轮次之间的状态分布差异很大,这本身就是重要信息。如果一个线程在所有采样轮次里都保持RUNNABLE,而且栈帧高度一致,那基本就是它在持续消耗CPU。
为了更直观,我还会在脚本结尾生成一个简单的Top线程栈频次表:
echo "[$(date '+%Y-%m-%d %H:%M:%S')] 生成Top线程栈频次表..." awk '/^"/{name=$0; getline; if ($0 ~ /java.lang.Thread.State/) { state=$0; while (getline && $0 !~ /^"/) frame_data[++f] = $0; if (frame_data[1] != "") { key = frame_data[1]; stack_count[key]++; } f=0; }} END { for (k in stack_count) print stack_count[k], k; }' "$OUT_DIR/all_jstack_merged.txt" | sort -rn | head -20 > "$OUT_DIR/top_thread_stacks.txt"这段逻辑的意思是:把全量线程栈文件里每个线程的第一栈帧提取出来,统计出现频次。第一栈帧出现次数多,说明大量线程正在执行同一个方法或同一个包下的代码,这往往是定位死循环的关键。
3.3 Top线程栈排序的判定逻辑
单纯地看第一栈帧有时还不够,因为有些线程会在多个方法间轮换。比如某个线程一会儿在A方法里计算,一会儿又在B方法里做IO,单看第一栈帧可能都只统计到1次,反而看不出问题。
更稳的做法是把每个线程的完整调用链压缩成一个字符串作为分组键。我后来在脚本里调整了统计方式:取栈顶前5帧拼接成一行,记录它出现的轮次数量和线程名。如果一个线程在10轮采样里出现了8轮以上,且同一个调用链重复出现,那几乎可以断定这个线程有异常。
# 提取线程名 + 栈顶5帧 作为指纹 awk '/^"/{ thread_name=$0; getline; # 线程状态行 getline; # 第一个栈帧 frame1=$0; getline; frame2=$0; getline; frame3=$0; getline; frame4=$0; getline; frame5=$0; fingerprint = thread_name " | " frame1 " | " frame2 " | " frame3 " | " frame4 " | " frame5; count[fingerprint]++; } END { for (f in count) if (count[f] >= 2) print count[f], f; }' "$OUT_DIR/all_jstack_merged.txt" | sort -rn | head -30 > "$OUT_DIR/recurring_thread_stacks.txt"这个指纹表比单纯的Top栈频次更可靠。我在实际故障中遇到过一个情况:某个线程栈顶第一帧一直是java.net.SocketInputStream.socketRead0,看起来像是在正常等待网络IO,但指纹表里显示了完整调用链,发现它在读Socket之前先执行了一个自定义的业务方法,然后再进入读的等待状态。一轮看下来才明白,其实是因为业务方法里有大量计算,读完socket又立刻做下一轮计算,CPU其实是被业务方法吃掉的。
4. 诊断数据的联动分析:从“线程高”到“根因确认”
脚本采集到的数据如果不做联动分析,价值会大打折扣。线程栈只是“人证”,GC日志、队列统计和IO状态是“物证”,两边的信息对上了,才能给问题定性。
4.1 配合队列深度判断是否积压
ActiveMQ的JMX里,每个队列都有EnqueueCount和DequeueCount两个计数器。你可以理解为“进队总数”和“出队总数”。两者的差值,就是当前积压消息数。诊断时我一般看两个比值:
- 单位时间内DequeueCount和EnqueueCount都高,且接近持平,说明broker在处理消息,CPU高是业务量大;
- EnqueueCount持续高于DequeueCount,差值持续放大,说明消费端明显掉队;
- 两边都不高,CPU却高,那问题一定不在消息分发链路上,大概率在某个后台线程、会话扫描或者GC上。
脚本里我预留了一个JMX采集入口,通过jcmd或者简单的Java程序调用ActiveMQ的JMX MBean。现场环境里如果已经开了JMX远程端口,也可以直接用curl访问JMX REST接口,但大多数内网环境不对外暴露,所以我更倾向于在broker同机执行一个本地的JMX快照命令。注意,采集JMX数据本身也有开销,采样频率不要和线程栈一样高,20秒一次就够了。
4.2 配合GC日志判断是否分配压力过大
jstat的-gcutil输出里,重点关注两个指标:Full GC次数(FGC)和Full GC耗时(FGCT)。如果两份连续采样之间,FGC增长了10次以上,FGCT也在快速增加,说明JVM把大量时间花在垃圾回收上,CPU高是GC线程燃烧的结果。
遇到这种情况,再去翻jstack里的线程状态,往往会看到两类特征:一是业务线程大量处于WAITING或者TIMED_WAITING,等待GC完成后才能继续;二是存在较多的Finalizer线程和Reference Handler线程。这两类线程在正常状态下几乎很少在栈顶出现,一旦出现,往往意味着进程里堆积了大量待回收对象。
ActiveMQ进程如果配置了较大的堆内存,却又没有合理配置-Xmn年轻代大小,或者把-XX:MaxTenuringThreshold调得过高,很容易出现对象晋升过快、老年代天天Full GC的尴尬局面。我处理过一个现场,堆给了6G,但年轻代只有512M,消息处理又是典型的“频繁创建小对象然后马上丢弃”模式,结果每几分钟就触发一次Full GC,CPU一直挂在GC线程上。后来我把年轻代扩大到2G,Full GC频次直接降了一个量级。
4.3 配合持久化IO判断是否刷盘拖累
ActiveMQ如果配置了KahaDB持久化,消息写入时同步刷盘的代价会影响CPU的假象。实际上,同步刷盘时线程大多处于IO等待状态,CPU使用率反而不会特别高;但如果磁盘本身性能下降,或者日志文件过多导致索引膨胀,后台的日志清理线程和索引合并线程会非常消耗CPU。
我在诊断脚本里加了一个可选的磁盘指标采集,通过iostat或者/proc/diskstats记录采样期间的IO等待百分比和IO吞吐量。当线程栈里出现大量KahaDB相关线程处于RUNNABLE,同时磁盘IO指标显示写入延迟偏高时,问题就不是单纯CPU高,而是存储子系统在拖累broker,CPU高只是表象。
5. 三次实战现场复盘:脚本是怎么一步步改出来的
写这套脚本不是一蹴而就的,我经历了三次较大的现场后,才把它从最初的“一个jstack循环”进化成现在这个相对完整的版本。每次复盘,都会往脚本里多补一个数据采集项。
5.1 第一次:业务线程死循环
那时候脚本还没有任何聚合统计,我只会手动敲jstack,然后肉眼找可疑栈。现场是某生产环境的broker CPU稳定在95%,队列深度不高,消息延迟却在涨。我连续看了五六张jstack,发现有一条业务线程每次都在同一个com.example.OrderProcessService.process方法附近打转。单看一份jstack,这顶多说明这个线程那一刻在处理消息;连看几份都是同样的栈帧位置,那就反常了。
后来去翻这段业务代码,发现开发在循环里用了while (retryCount < maxRetry),但retryCount的更新逻辑放在了一个永远进不去的if分支里,等于是一个隐藏的死循环。问题定位本身不难,但如果没有连续采样,我很难说服开发同事“就是你这段代码有问题”,因为单次jstack在他看来可能只是正常的业务执行。那次之后,我把“连续jstack采样 + 自动合并”加入了脚本的一等公民位置。
5.2 第二次:消费者拉取模式踩坑
第二次现场更隐蔽。一个业务团队反馈说消息消费变慢,但broker的负载CPU曲线却是锯齿形的,每隔几十秒冲一次高,冲到80%又掉下来。手工采了几次jstack都没抓到明显的异常线程,因为问题窗口太短了。
后来我把采样间隔缩短到2秒,连续采集30秒,终于在一堆采样文件里发现有个“ActiveMQ Session Scheduler”线程会周期性执行某个MessageDispatchChannel相关的栈帧。再结合IO统计,发现每次CPU冲高的时候,正好对应KahaDB日志文件进行一次预分配写入。问题根源是这条ActiveMQ的数据目录里,已经积累了超过十万个未清理的日志文件,每次元数据扫描都要遍历大量文件。
那次之后,我领悟到软件层面的CPU问题,有时必须把系统层面的文件句柄、磁盘IO统计也纳入诊断范畴。于是脚本加了两个输入源:lsof -p PID | wc -l统计文件句柄数量,以及iostat的磁盘指标采样。
5.3 第三次:小对象分配导致GC疯狂
第三次现场最有迷惑性。CPU高到报警,但jstack里所有业务线程状态都正常,没有死循环,也没有大范围阻塞。GC日志里Full GC次数在涨,但每次停顿也就几百毫秒,看起来不像能吃掉这么多CPU。
我用更新后的脚本去采集,发现jstat里Young GC(YGC)的次数在采样期间涨得飞快。活跃线程的栈帧又都集中在消息反序列化和字符串处理上,大量调用new String、toCharArray、正则匹配这类操作。真相是消息体里携带了一个极大的JSON字符串,消费者每次处理时都用正则做字段提取,而这个JDK版本的正则匹配又特别容易创建MatchResult临时对象,年轻代瞬间被打满。
那次之后,我在脚本里又加了两个统计项:线程栈中java.util.regex相关栈帧的出现次数,以及每个采样周期内YGC和FGC的增量。有了这些,就不需要再靠人眼去盯GC日志了。这也是为什么在这篇文章里,我反复强调脚本一定要按“现场取证”的思路去设计——你永远不知道下次故障会以什么面貌出现,但采集到的数据和做过的验证,能帮你快速绕过表象。
6. 脚本的边界与诊断后的处置思路
这个脚本虽然叫“诊断脚本”,但它解决的是“把事情看清楚”的问题,不是“一键修复”的问题。我见过不少同事拿着输出问我,脚本能不能直接给出“怎么办”的结论。我的回答往往是:能给结论的脚本,反而是危险脚本。生产环境里同样的线程栈可能对应完全不同的业务场景,自动判定很容易在关键时候误判。
先说脚本的边界。第一,它不能在容器环境下“即插即用”。如果ActiveMQ跑在Docker容器里,jstack要针对容器内的Java进程执行,脚本必须通过docker exec或者nsenter进去跑,而且容器内的JDK工具未必齐全。第二,它不能跨版本完全通用。ActiveMQ 5.x和6.x的线程命名、线程模型有一定差异,早期版本里有些线程名的统计规则要手动调。第三,如果broker已经处于极端过载状态,执行jstack本身会加剧压力,这种时候要先评估采集动作的代价。我遇到过一次CPU 100%的场景,跑采样时整个进程直接没有响应,那之后的处理就只能是先摘流量执行快速重启,采集数据只能作为事后复盘素材。
诊断之后的处置,我一般按这个顺序走:
- 如果定位到业务线程死循环或异常重试,立刻联系负责团队处理代码,并在broker层面临时限制该队列的消费者并发数;
- 如果定位到GC频繁,先检查JVM参数中的堆内存配置、年轻代比例和GC收集器选择,调整后观察至少一个完整业务周期的负载曲线;
- 如果定位到消息积压导致的分发压力,优先评估增加消费者实例和队列分片,而不是盲目给broker加CPU核数;
- 如果定位到存储层日志文件膨胀,则要清理过期的KahaDB日志文件、检查数据目录的磁盘空间,必要时做数据目录的迁移或压缩。
还有一个经验想特别说一下:无论问题怎样修复,都务必保留诊断目录的完整输出。很多问题不是一次就能定性明白的,当时看起来不相关的线程栈片段,在后续做性能复盘时往往反而是关键线索。我现在的习惯是把每次故障的诊断目录压缩存档,文件名里带上日期时间和当时的核心指标摘要,需要追溯的时候直接翻历史记录。这套脚本本身,也因为它能在故障现场快速留下这么一份“完整现场档案”,反而成了我这边多少有点依赖的工具。
是的,ActiveMQ的高CPU问题,本质上是一个“定位工具是否拿得对、数据是否采得全”的问题。脚本只是把最基本的排查动作自动化了,真正值钱的部分——怎么解读数据,怎么建立线程栈、队列深度、GC状态和系统IO的关联——永远在人的脑子里。