WE lag at event handler
v9-l10n opened this issue ยท 6 comments
Versions
WorldEdit version: 7.2.2
Platform version: Paper 1.16.5 build 464
Describe the bug
The server runs normally and TPS drops from 20 to 1 for some time.
To Reproduce
I have no idea, this issue has been around us for a while. We thought it would be some players that flooding with packets, but even we added packet limiter with a lower pps limit we still see this happens from time to time.
There is no WE operation ongoing while such issue happens.
Expected behavior
Server running normally.
Screenshots
None.
Additional context
Some stack trace
[10:39:01] [Paper Watchdog Thread/ERROR]: --- DO NOT REPORT THIS TO PAPER - THIS IS NOT A BUG OR A CRASH - git-Paper-445 (MC: 1.16.5) ---
[10:39:01] [Paper Watchdog Thread/ERROR]: The server has not responded for 20 seconds! Creating thread dump
[10:39:01] [Paper Watchdog Thread/ERROR]: ------------------------------
[10:39:01] [Paper Watchdog Thread/ERROR]: Server thread dump (Look for plugins here before reporting to Paper!):
[10:39:01] [Paper Watchdog Thread/ERROR]: ------------------------------
[10:39:01] [Paper Watchdog Thread/ERROR]: Current Thread: Server thread
[10:39:01] [Paper Watchdog Thread/ERROR]: PID: 35 | Suspended: false | Native: false | State: RUNNABLE
[10:39:01] [Paper Watchdog Thread/ERROR]: Stack:
[10:39:01] [Paper Watchdog Thread/ERROR]: [email protected]/java.lang.ThreadLocal$ThreadLocalMap.expungeStaleEntry(ThreadLocal.java:637)
[10:39:01] [Paper Watchdog Thread/ERROR]: [email protected]/java.lang.ThreadLocal$ThreadLocalMap.remove(ThreadLocal.java:519)
[10:39:01] [Paper Watchdog Thread/ERROR]: [email protected]/java.lang.ThreadLocal.remove(ThreadLocal.java:242)
[10:39:01] [Paper Watchdog Thread/ERROR]: com.sk89q.worldedit.session.request.Request.reset(Request.java:111)
[10:39:01] [Paper Watchdog Thread/ERROR]: com.sk89q.worldedit.extension.platform.PlatformManager.handleBlockInteract(PlatformManager.java:321)
[10:39:01] [Paper Watchdog Thread/ERROR]: jdk.internal.reflect.GeneratedMethodAccessor167.invoke(Unknown Source)
[10:39:01] [Paper Watchdog Thread/ERROR]: [email protected]/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[10:39:01] [Paper Watchdog Thread/ERROR]: [email protected]/java.lang.reflect.Method.invoke(Method.java:564)
[10:39:01] [Paper Watchdog Thread/ERROR]: com.sk89q.worldedit.util.eventbus.MethodEventHandler.dispatch(MethodEventHandler.java:58)
[10:39:01] [Paper Watchdog Thread/ERROR]: com.sk89q.worldedit.util.eventbus.EventHandler.handleEvent(EventHandler.java:73)
[10:39:01] [Paper Watchdog Thread/ERROR]: com.sk89q.worldedit.util.eventbus.EventBus.nonwrapped_dispatch(EventBus.java:193)
[10:39:01] [Paper Watchdog Thread/ERROR]: com.sk89q.worldedit.util.eventbus.EventBus.dispatch(EventBus.java)
[10:39:01] [Paper Watchdog Thread/ERROR]: com.sk89q.worldedit.util.eventbus.EventBus.nonwrapped_post(EventBus.java:181)
[10:39:01] [Paper Watchdog Thread/ERROR]: com.sk89q.worldedit.util.eventbus.EventBus.post(EventBus.java)
[10:39:01] [Paper Watchdog Thread/ERROR]: com.sk89q.worldedit.WorldEdit.handleBlockLeftClick(WorldEdit.java:689)
[10:39:01] [Paper Watchdog Thread/ERROR]: com.sk89q.worldedit.bukkit.WorldEditListener.onPlayerInteract(WorldEditListener.java:118)
[10:39:01] [Paper Watchdog Thread/ERROR]: com.destroystokyo.paper.event.executor.asm.generated.GeneratedEventExecutor20.execute(Unknown Source)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//org.bukkit.plugin.EventExecutor.lambda$create$1(EventExecutor.java:69)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//org.bukkit.plugin.EventExecutor$$Lambda$4799/0x00007f38e9ffacb0.execute(Unknown Source)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//co.aikar.timings.TimedEventExecutor.execute(TimedEventExecutor.java:76)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:70)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:607)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//org.bukkit.craftbukkit.v1_16_R3.event.CraftEventFactory.callPlayerInteractEvent(CraftEventFactory.java:511)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//org.bukkit.craftbukkit.v1_16_R3.event.CraftEventFactory.callPlayerInteractEvent(CraftEventFactory.java:474)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//org.bukkit.craftbukkit.v1_16_R3.event.CraftEventFactory.callPlayerInteractEvent(CraftEventFactory.java:469)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_16_R3.PlayerInteractManager.a(PlayerInteractManager.java:154)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_16_R3.PlayerConnection.a(PlayerConnection.java:1485)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_16_R3.PacketPlayInBlockDig.a(SourceFile:40)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_16_R3.PacketPlayInBlockDig.a(SourceFile:10)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_16_R3.PlayerConnectionUtils.lambda$ensureMainThread$1(PlayerConnectionUtils.java:23)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_16_R3.PlayerConnectionUtils$$Lambda$6314/0x00007f380d2d64b0.run(Unknown Source)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_16_R3.TickTask.run(SourceFile:18)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_16_R3.IAsyncTaskHandler.executeTask(IAsyncTaskHandler.java:136)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_16_R3.IAsyncTaskHandlerReentrant.executeTask(SourceFile:23)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_16_R3.IAsyncTaskHandler.executeNext(IAsyncTaskHandler.java:109)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_16_R3.MinecraftServer.bb(MinecraftServer.java:1132)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_16_R3.MinecraftServer.executeNext(MinecraftServer.java:1125)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_16_R3.IAsyncTaskHandler.executeAll(IAsyncTaskHandler.java:95)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_16_R3.MinecraftServer.a(MinecraftServer.java:1261)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_16_R3.MinecraftServer.w(MinecraftServer.java:996)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_16_R3.MinecraftServer.lambda$a$0(MinecraftServer.java:173)
[10:39:01] [Paper Watchdog Thread/ERROR]: app//net.minecraft.server.v1_16_R3.MinecraftServer$$Lambda$3161/0x00007f39707d2040.run(Unknown Source)
[10:39:01] [Paper Watchdog Thread/ERROR]: [email protected]/java.lang.Thread.run(Thread.java:832)
[10:39:01] [Paper Watchdog Thread/ERROR]: ------------------------------
[10:39:01] [Paper Watchdog Thread/ERROR]: --- DO NOT REPORT THIS TO PAPER - THIS IS NOT A BUG OR A CRASH ---
[10:39:01] [Paper Watchdog Thread/ERROR]: ------------------------------
Please let me know if you need any further information.
Last time I saw this it was a Java bug and unrelated to WorldEdit. Something about a map implementation that could get stuck in a near-infinite loop in G1GC.
Disable G1GC in your startup flags and it should be resolved.
Thank you for your reply. However we are using ZGC, there is no G1GC argument in the startup line.
Our startup command is
java -Xms16G -Xmx16G -server -XX:+IgnoreUnrecognizedVMOptions -XX:+UnlockExperimentalVMOptions -XX:+UnlockDiagnosticVMOptions -XX:+UseGCOverheadLimit -XX:+ParallelRefProcEnabled -XX:-OmitStackTraceInFastThrow -XX:+ShowCodeDetailsInExceptionMessages -XX:+DisableExplicitGC -XX:+UseZGC -XX:-ZUncommit -XX:ZUncommitDelay=600 -XX:SoftMaxHeapSize=8G -XX:+UseCMoveUnconditionally -XX:+UseFPUForSpilling -XX:+UseNewLongLShift -XX:+UseVectorCmov -XX:+UseXMMForArrayCopy -XX:+UseXmmI2D -XX:+UseXmmI2F -XX:+UseXmmLoadAndClearUpper -XX:+UseXmmRegToRegMoveAll -jar paperclip.jar --nogui
A handful of people seem to get this issue occasionally (I can find two on our discord searching for "threadlocal"). Unfortunately it's completely out of our control and there's probably some deeper issue with your specific jvm/system setup causing threadlocals to hang.
edit: according to timings from both those users, one was using g1gc, other was using zgc, one was on java11, one was on java14. so that doesn't really narrow it down unfortunately.
edit2: also for reference, https://bugs.openjdk.java.net/browse/JDK-8182982
Alright, we will switch to openjdk 11 with openj9 and report back if we could find anything useful.
Thank you for your help again.
When I investigated this a while ago - the issue was that due to a bug in G1GC, and GCs that somewhat built off it (such as ZGC and Shenandoah), on some machines ThreadLocal calls can get stuck for a while. It can happen at random ThreadLocal calls, but as WorldEdit uses them in interactions - it's statistically the most likely to trigger one (due to frequency).
The only solution I saw was to use the CMS garbage collector. This isn't a WorldEdit-specific issue, or even a Minecraft one. It's a Java bug that also affects major products like ElasticSearch.
Update.
OpenJ9 reproduced this issue. However we get another paper error report that complaining 2.47M packets.
[21:30:28 ERROR]: ------------------------------
[21:30:28 ERROR]: Server thread dump (Look for plugins here before reporting to Paper!):
[21:30:28 ERROR]: Handling packet for player '[redacted]', UUID: [redacted]
[21:30:28 ERROR]: Position: world: 'world' at location (69.48246685810037, 76.17675927506424, 361.5872717742033)
[21:30:28 ERROR]: Total packets processed on the main thread for all players: 2470758
[21:30:28 ERROR]: ------------------------------
[21:30:28 ERROR]: Current Thread: Server thread
[21:30:28 ERROR]: PID: 44 | Suspended: false | Native: false | State: RUNNABLE
[21:30:28 ERROR]: Stack:
[21:30:28 ERROR]: java.base/java.lang.ThreadLocal$ThreadLocalMap.expungeStaleEntry(Unknown Source)
[21:30:28 ERROR]: java.base/java.lang.ThreadLocal$ThreadLocalMap.remove(Unknown Source)
[21:30:28 ERROR]: java.base/java.lang.ThreadLocal.remove(Unknown Source)
[21:30:28 ERROR]: com.sk89q.worldedit.session.request.Request.reset(Request.java:111)
[21:30:28 ERROR]: com.sk89q.worldedit.extension.platform.PlatformManager.handlePlayerInput(PlatformManager.java:404)
[21:30:28 ERROR]: jdk.internal.reflect.GeneratedMethodAccessor39.invoke(Unknown Source)
[21:30:28 ERROR]: java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
[21:30:28 ERROR]: java.base/java.lang.reflect.Method.invoke(Unknown Source)
[21:30:28 ERROR]: com.sk89q.worldedit.util.eventbus.MethodEventHandler.dispatch(MethodEventHandler.java:58)
[21:30:28 ERROR]: com.sk89q.worldedit.util.eventbus.EventHandler.handleEvent(EventHandler.java:73)
[21:30:28 ERROR]: com.sk89q.worldedit.util.eventbus.EventBus.dispatch(EventBus.java:193)
[21:30:28 ERROR]: com.sk89q.worldedit.util.eventbus.EventBus.post(EventBus.java:181)
[21:30:28 ERROR]: com.sk89q.worldedit.WorldEdit.handleArmSwing(WorldEdit.java:625)
[21:30:28 ERROR]: com.sk89q.worldedit.bukkit.WorldEditListener.onPlayerInteract(WorldEditListener.java:128)
[21:30:28 ERROR]: com.destroystokyo.paper.event.executor.asm.generated.GeneratedEventExecutor19.execute(Unknown Source)
[21:30:28 ERROR]: org.bukkit.plugin.EventExecutor.lambda$create$1(EventExecutor.java:69)
[21:30:28 ERROR]: org.bukkit.plugin.EventExecutor$$Lambda$4861/0x0000000000000000.execute(Unknown Source)
[21:30:28 ERROR]: co.aikar.timings.TimedEventExecutor.execute(TimedEventExecutor.java:80)
[21:30:28 ERROR]: org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:70)
[21:30:28 ERROR]: org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:607)
[21:30:28 ERROR]: org.bukkit.craftbukkit.v1_16_R3.event.CraftEventFactory.callPlayerInteractEvent(CraftEventFactory.java:528)
[21:30:28 ERROR]: org.bukkit.craftbukkit.v1_16_R3.event.CraftEventFactory.callPlayerInteractEvent(CraftEventFactory.java:491)
[21:30:28 ERROR]: org.bukkit.craftbukkit.v1_16_R3.event.CraftEventFactory.callPlayerInteractEvent(CraftEventFactory.java:486)
[21:30:28 ERROR]: org.bukkit.craftbukkit.v1_16_R3.event.CraftEventFactory.callPlayerInteractEvent(CraftEventFactory.java:482)
[21:30:28 ERROR]: net.minecraft.server.v1_16_R3.PlayerConnection.a(PlayerConnection.java:2104)
[21:30:28 ERROR]: net.minecraft.server.v1_16_R3.PacketPlayInArmAnimation.a(SourceFile:31)
[21:30:28 ERROR]: net.minecraft.server.v1_16_R3.PacketPlayInArmAnimation.a(SourceFile:9)
[21:30:28 ERROR]: net.minecraft.server.v1_16_R3.PlayerConnectionUtils.lambda$ensureMainThread$1(PlayerConnectionUtils.java:43)
[21:30:28 ERROR]: net.minecraft.server.v1_16_R3.PlayerConnectionUtils$$Lambda$5986/0x0000000000000000.run(Unknown Source)
[21:30:28 ERROR]: net.minecraft.server.v1_16_R3.TickTask.run(SourceFile:18)
[21:30:28 ERROR]: net.minecraft.server.v1_16_R3.IAsyncTaskHandler.executeTask(IAsyncTaskHandler.java:136)
[21:30:28 ERROR]: net.minecraft.server.v1_16_R3.IAsyncTaskHandlerReentrant.executeTask(SourceFile:23)
[21:30:28 ERROR]: net.minecraft.server.v1_16_R3.IAsyncTaskHandler.executeNext(IAsyncTaskHandler.java:109)
[21:30:28 ERROR]: net.minecraft.server.v1_16_R3.MinecraftServer.bb(MinecraftServer.java:1192)
There were multiple similar logs and pointing to different player each time. However from our monitoring the peak PPS on the NIC observed was around 4K~8K and at peak of 11K, not 2M. There are ~100 players online and mspt at 20ms in normal state.
Switched to Tuinity with default packet limiter configuration has no help on this - and we still see same PPS which should be normal.
Hope this helps.