记一次战斗服务器 CPU 打满 100% 且无法恢复的排查arthas iotop gdb 全链路这是一次游戏服务器压测期间的真实排查记录现象是 CPU 被打满后停止压测也不恢复最后用 arthas、vmstat/iostat/iotop、gdb 一路追到一个意料之外的根因。文末整理了这类问题的通用排查套路希望对你有帮助。一、背景项目是一个带战斗校验的玩法客户端与服务器共用同一套战斗逻辑服务器侧通过 JNI 调用一个基于 xLua 封装的本地校验库战斗结束后服务器重放校验一遍保证战斗结果可信。压测阶段发现战斗服务器后文称战斗服的 CPU 表现异常于是有了这次排查。二、现象先把问题说清楚先看现象这里其实有三个关键信息压测条件很轻不到 10 个压测机器人请求间隔 3 秒。CPU 占用是线性打满1 个机器人就把单个核吃到 100%2 个机器人占 2 个核机器人数量超过 CPU 核数后整机打满。两个反常点停止机器人后CPU 依然 100%不释放较高概率下JVM 直接宕机机器上生成了 core 文件。排查技巧 #1拿到问题先别急着动手把现象写清楚尤其是反常点。“停止压测 CPU 不恢复说明进程并不是忙完了在喘气”而是还有活没干完——这一条在后面直接帮我们锁定了根因。三、排查过程3.1 第一步定位热点线程arthasCPU 高第一步永远是先看是谁在吃 CPU。登录机器用 arthas attach 上进程# 启动 arthasjava-jararthas-boot.jar# 先看整体哪些线程 CPU 高dashboard# 查看线程 CPU 占用排行thread-n3结果占用 CPU 最高的是负责处理战斗校验消息的工作线程堆栈显示它停在Lua 本地库的调用里。$ thread -n 3 BattleCheck-Worker-4 Id57 cpuUsage98.7% deltaTime98ms time120300ms RUNNABLE at com.xxx.battle.NativeChecker.check(NativeChecker.java:-1) at com.xxx.battle.BattleVerifyTask.run(BattleVerifyTask.java:88) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:1149) BattleCheck-Worker-2 Id55 cpuUsage97.6% deltaTime97ms time119800ms RUNNABLE at com.xxx.battle.NativeChecker.check(NativeChecker.java:-1) at com.xxx.battle.BattleVerifyTask.run(BattleVerifyTask.java:88) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:1149) BattleCheck-Worker-1 Id54 cpuUsage97.1% deltaTime97ms time118400ms RUNNABLE at com.xxx.battle.NativeChecker.check(NativeChecker.java:-1) at com.xxx.battle.BattleVerifyTask.run(BattleVerifyTask.java:88)线程名与包名已脱敏可以看到前几名全是校验工作线程堆栈的栈顶都停在 native 方法上。只用一个线程名还不能下结论但堆栈给了我们第一个怀疑对象。于是做一个对照组实验把 Lua 校验逻辑关掉同样的压力再跑一遍 →一切正常。问题范围就此锁定出在本地校验库的逻辑上。3.2 第二步最小化复现把压力降到最小只跑 1 个机器人、3 秒请求间隔。toptop - 15:32:41 up 45 days, 3 users, load average: 1.02, 0.65, 0.28 Tasks: 183 total, 1 running, 182 sleeping, 0 stopped, 0 zombie %Cpu(s): 12.6 us, 0.8 sy, 0.0 ni, 86.4 id, 0.2 wa, 0.0 hi, 0.0 si, 0.0 st MiB Mem : 15872.0 total, 6231.4 free, 4520.8 used, 5120.8 buff/cache PID USER PR NI VIRT RES SHR S %CPU %MEM TIME COMMAND 12345 game 20 0 9681040 286432 12088 S 99.7 1.8 12:35.68 java单核被打满8 核机器上整体 us 只有 12.6%但 java 进程单个 CPU 已经 99.7%top 的进程 CPU 按单核算。单个机器人也能把一个核吃到 100%。这说明问题与并发竞争、多线程调度无关单线程执行一次校验本身就有问题也解释了几个机器人占几个核——每个校验任务都独占一个核在跑。3.3 第三步换个角度——CPU 高不一定是在计算到这里最容易掉进的坑是认定这是校验计算太重然后一头扎进算法优化。先别急。回头看现象里的反常点机器人停了 CPU 为什么不释放如果只是计算慢计算完就该闲下来。除非——它根本不是在算或者在算之外还在干别的。CPU 利用率里 user/sys/iowait 的构成可以告诉我们答案。先看整体 IO 情况vmstat1procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 2 0 0 6379432 122484 5242880 0 0 12 68432 9821 15320 11 2 85 2 0 1 0 0 6372356 122484 5242880 0 0 0 91136 9973 16204 12 3 83 2 0 1 0 0 6370512 122484 5242880 0 0 0 87296 9891 15877 12 3 83 2 0输出里 bo每秒写出的磁盘块数一栏高达 7~9 万说明进程在高频写磁盘。再用 iostat 确认具体是哪块盘、什么速率iostat-x1Device r/s w/s rkB/s wkB/s rrqm/s wrqm/s r_await w_await aqu-sz rareq-sz wareq-sz %util vda 0.00 6231.00 0.00 75842.00 0.00 12.00 0.00 1.86 11.32 0.00 12.17 98.40 vda1 0.00 6231.00 0.00 75842.00 0.00 12.00 0.00 1.86 11.32 0.00 12.17 98.40确认了磁盘写入速率异常高%util 已接近 100%。接下来用 iotop 定位是哪个进程在写iotop-o# 只显示有 IO 活动的进程Total DISK READ : 0.00 B/s | Total DISK WRITE : 74.55 M/s Actual DISK READ: 0.00 B/s | Actual DISK WRITE: 72.31 M/s TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND 12345 be/4 game 0.00 B/s 71.83 M/s 0.00 % 85.20 % java -jar battle-server.jar 12346 be/4 game 0.00 B/s 2.41 M/s 0.00 % 3.10 % java -jar battle-server.jar结果就是战斗服进程自己在不停地写磁盘写入速率约 70 MB/s。3.4 第四步找到真凶——一个疯狂增长的日志文件进程在写什么顺着找进程打开的、大小在持续增长的文件很快锁定目标Lua 库自己的 log 文件。$ ls -lh /home/game/server/log/lua.log -rw-r--r-- 1 game game 1.3G Jun 3 17:01 lua.log $ ls -lh /home/game/server/log/lua.log # 约 10 秒后再看一次 -rw-r--r-- 1 game game 2.1G Jun 3 17:02 lua.log观察发现两个事实这个 log 文件在持续高速增长机器人已经停了日志还在涨。第二条正是CPU 不释放的答案本地库里有逻辑在循环写日志只要进程活着它就一直写——写文件是系统调用系统调用开销表现成 CPU 占用所以看起来像计算打满停了压力也不下来。验证很简单关闭 Lua 库的日志开关再跑同样的压测 → CPU 恢复正常。第一个问题CPU 打满且不释放定位完毕根因是本地库的日志逻辑修复需要库的维护方处理。排查技巧 #2CPU 100% 先分清是 user 还是 sys/iowait。看起来在计算和真的在计算是两回事本例最初的误导就在于堆栈看起来像计算密集。当现象和推理矛盾时停了不恢复优先怀疑你的假设而不是现象。3.5 第五步收口一个再查下一个——宕机与真·计算重第一个问题定位后还剩两个遗留问题继续逐个处理。问题 A关了日志之后人数一多 CPU 还是高且有概率宕机。先处理宕机。机器上已经生成了 core 文件直接用 gdb 分析gdbjava可执行文件core文件(gdb)bt# 查看崩溃时的调用堆栈Program terminated with signal SIGSEGV, Segmentation fault. #0 0x00007f8b2c1d3e55 in luaV_execute () from /home/game/server/lib/libbattlecheck.so #1 0x00007f8b2c1c9a12 in luaD_call () from /home/game/server/lib/libbattlecheck.so #2 0x00007f8b2c1b7f34 in luaD_pcall () from /home/game/server/lib/libbattlecheck.so #3 0x00007f8b2c1a5c21 in battle_check_run () from /home/game/server/lib/libbattlecheck.so #4 0x00007f8b2c194d88 in Java_com_xxx_battle_NativeChecker_check () from /home/game/server/lib/libbattlecheck.so #5 0x00007f8b0402a318 in ?? ()堆栈明确指向 Lua 库的执行逻辑——宕机同样是本地库的问题交给库的维护方跟进。排查技巧 #3涉及 JNI / 本地库的 Java 进程JVM 层的工具arthas、jstack只能看到进入 native 就断了core dump gdb 是穿透 native 层的唯一手段。平时确保服务器开启了 core dumpulimit -c unlimited关键时候才有的查。问题 B关了日志后 CPU 仍然偏高。这次是真的计算重了。统计单场战斗的校验耗时服务端校验日志[INFO] battle verify cost: stage1 rounds8 cost201ms [INFO] battle verify cost: stage2 rounds11 cost268ms [INFO] battle verify cost: stage5 rounds19 cost415ms [INFO] battle verify cost: stage8 rounds27 cost573ms [INFO] battle verify cost: stage1 rounds8 cost191ms - 换号重打第 1 关数据说话第一关校验耗时约 200ms关卡越深、回合数越多耗时越长。按这个量级多机器人并发时打满 CPU 是必然的——这不是 bug是校验逻辑本身的性能问题优化方案同样需要库的维护方评估。四、复盘这次排查的通用套路整个过程串起来就是一张现象 → 工具 → 结论的路线图步骤现象/问题用的工具得到的结论1谁在吃 CPUarthasdashboard / thread工作线程堆栈停在 Lua 本地库2是并发问题吗最小化复现1 个机器人 top不是单次执行本身就有问题3真的是在计算吗vmstat → iostat → iotop进程在疯狂写磁盘4在写什么观察文件大小增长Lua 日志文件停了压力还在写 → CPU 不释放的根因5为什么宕机gdb 分析 core dump崩在本地库执行逻辑6为什么还是慢校验耗时统计单次校验本身太重属性能问题几条可复用的经验把现象写清楚抓住反常点。停了不恢复是本次排查最重要的线索对照组实验是最快的定位手段关闭怀疑点 → 正常范围立刻缩小CPU 高先分类user / sys / iowait 各自意味着完全不同的方向一次只收口一个问题定位完日志问题再去查宕机多线并进容易乱跨语言调用是排查盲区JNI 边界上准备好 core dump 和 gdb。五、写在最后这次排查最后虽然是甩锅给了本地库的维护方但把问题准确定位、把证据堆栈、IO 数据、core 分析、耗时数据整理清楚交出去本身就是服务端开发的核心能力——否则两边只能互相猜。如果你也遇到过看起来是 CPU 计算密集、最后根因却在别处的案例欢迎在评论区聊聊。