一次平常的 Minecraft 服务器运维,在把服务端 /stop 后,却发现服务端进程久久未能关闭
反常必有妖,让我看看是谁在干坏事
问题排查
环境
先列一下基本环境:
Minecraft 1.20.1
Fabric loader 0.15.11,带不少创造服相关 mod
OpenJDK 21.0.4
初步分析
由于 MC 服务端是带着 MCDR 运行的,先用 !!MCDR status 看一下进程 PID
拿到 java 进程的 PID 4409 后,用 jstack 工具看一下每个线程都在干啥,看看有没有啥异常的
12$ jstack 4409 > jstack.out$ cat jstack.out | grep 'Server Thread'
找不到 MC 服务端主线程 Server Thread,说明 MC 服务端主线程已经结束了。那估计是有非 daemon thread 在搞事情
123$ cat jstack.out | grep ' #' | grep -v daemon"DestroyJavaVM" #79 [4418] prio=5 os_prio=0 cpu=6699.00ms elapsed=628699.38s tid=0x00007f041002a3c0 nid=4418 waiting on condition [0x0000000000000000]"Timer-1" #6712 [54030] prio=8 os_prio=0 cpu=0.50ms elapsed=266535.65s tid=0x00007f02bd8d8270 nid=54030 in Object.wait() [0x00007f02686d4000]
这个 Timer-1 进程看上去很可疑,看下它的堆栈
1234567891011$ cat jstack.out | grep '#6712' -A 9"Timer-1" #6712 [54030] prio=8 os_prio=0 cpu=0.50ms elapsed=266535.65s tid=0x00007f02bd8d8270 nid=54030 in Object.wait() [0x00007f02686d4000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait0([email protected]/Native Method) - waiting on
基本能确定是这个 TimerThread 在搞事情了
java.util.Timer
阅读了下 jdk21 里 java.util.Timer 的代码,能看到在默认构造函数的情况下,Timer 会创建一个非 daemon 的线程
12345678910111213141516171819public Timer() { this("Timer-" + serialNumber());}public Timer(boolean isDaemon) { this("Timer-" + serialNumber(), isDaemon);}public Timer(String name) { this(name, false);}public Timer(String name, boolean isDaemon) { var threadReaper = new ThreadReaper(queue, thread); this.cleanup = CleanerFactory.cleaner().register(this, threadReaper); thread.setName(name); thread.setDaemon(isDaemon); thread.start();}
先猜一个,有坏东西创建一个非 daemon 的 timer 且忘了关,导致服务端关不掉
先看看是不是 mojang 在干坏事。在 MC 1.20.1 的源代码里翻了一遍 java.util.Timer 的引用,
服务端的相关代码里只看到 watchdog 里有用 timer,且那个 timer 是拿来兜底关进程的,应该并不相关
怀疑是不是 mod 在干坏事了
heap dump
一个一个翻 mod 代码可能比较费时间,先再从现场保留一些信息下来,搞个 heap dump 看下
1jmap -dump:format=b,file=heapdump.hprof 4409
把 heapdump.hprof 搞到本地,拿 jprofiler 打开,过滤下 java.util.Timer 对象,发现只有俩
找到那个 tid=6712 的对象 0x1728d8
看看传入引用
发现凶手了,是 WorldEdit(worldedit-mod-7.2.15.jar) 在干坏事
确定问题
直接把 mod 的 jar 搞下来,反编译一下,这样比翻 git 仓库的版本更快也更准些
找到 com.sk89q.worldedit.command.util.FutureProgressListener 这个类
123public class FutureProgressListener implements Runnable { private static final Timer timer = new Timer(); // ...
罪魁祸首找到了。这个 FutureProgressListener 类搞了个全局的 timer,还是非 daemon thread 的 timer,搞的服务端关也关不掉
考虑到这个问题并非是必现的(如果必现,早就被人发现了),再去看下代码。如果 FutureProgressListener 这个类被加载了,其 static timer 对象就会被构造,就会导致服务端关不掉,
那就意味着,只要服务端从不使用、不加载这个 FutureProgressListener 类,就不会有问题
看一下 FutureProgressListener 在 WorldEdit 代码里的使用情况,能看到它会在几个异步指令的执行处被触发(代码关键字:com.sk89q.worldedit.command.util.AsyncCommandBuilder#buildAndExec),比如
加载、保存 schematic 文件
/searchitem、listchunks 等指令
如果服务器运行过程中没触发相关逻辑的话,服务端即可正常关闭
尝试着复现了一下:仅保留 worldedit-mod-7.2.15.jar 这个 mod,开服,输入 /searchitem stone,/stop,服务端果然卡着了
确定了触发路径,再看看影响范围,这次不得不打开 WorldEdit 的 git 仓库 了
对着 private static final Timer timer = new Timer(); 这行来一个 Git > Show History for Selection,确定影响范围:
从 7.0.0-beta-05 开始的版本,均受影响。这基本上可以说是,MC 1.13 以上的,至目前最新的 MC 1.21 的 WorldEdit 7.3.7,均受影响。影响范围还蛮大的
这么看上去,说不定这个 bug 也是 MCDR 的某个疑难 issue 的根因
不管怎么说,得给 WorldEdit 交了个 issue。搜下 issue 列表,发现了个 已存在的 issue,但被 close 了,
那就补上一波详细说明:https://github.com/EngineHub/WorldEdit/issues/2459#issuecomment-2412020684
总的来讲,WorldEdit 存在两个影响服务器支持关闭的 bug:
FutureProgressListener 存在一个非 daemon thread 运行的 Timer,导致服务端关闭时会永久卡住。这也是本文发现的 bug
WorldEdit.getInstance().getExecutorService() 未在服务器关闭时 shutdown。这最多会卡住服务端 60s
等 WorldEdit 修 bug 还得好一会时间 说不定还会被 reverted,并且 WorldEdit 大概率不会去照顾老版本,那不如自己动手整个 fix mod,拎起 mixin 直接上:
https://github.com/Fallen-Breath/worldedit-hang-fix