Server deadlock in mount call
LemADEC opened this issue ยท 6 comments
Useful information to include:
- Minecraft version 1.12.2, forge-14.23.5.2838
- CC: Tweaked version 1.12.2-1.84.0
- WarpDrive version
- Detailed reproduction steps:
A server deadlock was observed for more than 60 s while being stuck in the mount() method.
The related code is https://github.com/LemADEC/WarpDrive/blob/4164613146996544556e26840882e3ef9ca88dfe/src/main/java/cr0s/warpdrive/block/TileEntityAbstractInterfaced.java#L532
Issue was seen once, not sure what triggered it
I'm assuming this hasn't happened again for three months, and so I'm going to close this for now. If this issue occurs again, or anyone else experiences it, please take a thread-dump as described above and I'll reopen the issue.
It can show all threads, but I filter it by default on the server thread so I get a proper CPU load estimation. We'll see next time it occurs to get more infos.
Can you provide the full thread dump? It's hard to tell what's deadlocking without knowing what else is holding those locks.
That's the full stack seen by the profiler. I had to kill the server to recover.
Console commands were not responding.
The debug logs ended like so:
[17:36:29] [Server thread/INFO] [warpdrive]: TileEntityShipCore 'USS Hopster' xxx Connected Playing sound effect 'net.minecraft.util.SoundEvent@596d0bc4' soundThreshold 155 warmupTime 155
[17:36:32] [Server thread/DEBUG] [FML]: Gathering id map for writing to world save Sadistic
[17:36:58] [luckperms-hikari housekeeper/DEBUG] [me.lucko.luckperms.lib.hikari.pool.HikariPool]: luckperms-hikari - Pool stats (total=10, active=0, idle=10, waiting=0)
[17:36:58] [pool-3-thread-34/INFO] [net.minecraft.server.dedicated.DedicatedServer]: FSG City planets are filled with Cyberware borgs, get good gear before landing with your ship!
[17:37:28] [luckperms-hikari housekeeper/DEBUG] [me.lucko.luckperms.lib.hikari.pool.HikariPool]: luckperms-hikari - Pool stats (total=10, active=0, idle=10, waiting=0)
[17:37:58] [luckperms-hikari housekeeper/DEBUG] [me.lucko.luckperms.lib.hikari.pool.HikariPool]: luckperms-hikari - Pool stats (total=10, active=0, idle=10, waiting=0)
[17:38:28] [luckperms-hikari housekeeper/DEBUG] [me.lucko.luckperms.lib.hikari.pool.HikariPool]: luckperms-hikari - Pool stats (total=10, active=0, idle=10, waiting=0)
[17:38:58] [luckperms-hikari housekeeper/DEBUG] [me.lucko.luckperms.lib.hikari.pool.HikariPool]: luckperms-hikari - Pool stats (total=10, active=0, idle=10, waiting=0)
[17:39:01] [luckperms-hikari connection closer/DEBUG] [me.lucko.luckperms.lib.hikari.pool.PoolBase]: luckperms-hikari - Closing connection me.lucko.luckperms.lib.mysql.jdbc.JDBC4Connection@7eed11fb: (connection has passed maxLifetime)
[17:39:01] [luckperms-hikari connection adder/DEBUG] [me.lucko.luckperms.lib.hikari.pool.HikariPool]: luckperms-hikari - Added connection me.lucko.luckperms.lib.mysql.jdbc.JDBC4Connection@1e8c8508
[17:39:03] [luckperms-hikari connection closer/DEBUG] [me.lucko.luckperms.lib.hikari.pool.PoolBase]: luckperms-hikari - Closing connection me.lucko.luckperms.lib.mysql.jdbc.JDBC4Connection@eb6770a: (connection has passed maxLifetime)
[17:39:03] [luckperms-hikari connection adder/DEBUG] [me.lucko.luckperms.lib.hikari.pool.HikariPool]: luckperms-hikari - Added connection me.lucko.luckperms.lib.mysql.jdbc.JDBC4Connection@5fb18f33
[17:39:12] [luckperms-hikari connection closer/DEBUG] [me.lucko.luckperms.lib.hikari.pool.PoolBase]: luckperms-hikari - Closing connection me.lucko.luckperms.lib.mysql.jdbc.JDBC4Connection@3fd01bc0: (connection has passed maxLifetime)
[17:39:12] [luckperms-hikari connection adder/DEBUG] [me.lucko.luckperms.lib.hikari.pool.HikariPool]: luckperms-hikari - Added connection me.lucko.luckperms.lib.mysql.jdbc.JDBC4Connection@74c2668b
[17:39:17] [luckperms-hikari connection closer/DEBUG] [me.lucko.luckperms.lib.hikari.pool.PoolBase]: luckperms-hikari - Closing connection me.lucko.luckperms.lib.mysql.jdbc.JDBC4Connection@4ed1e0a1: (connection has passed maxLifetime)
[17:39:17] [luckperms-hikari connection adder/DEBUG] [me.lucko.luckperms.lib.hikari.pool.HikariPool]: luckperms-hikari - Added connection me.lucko.luckperms.lib.mysql.jdbc.JDBC4Connection@3ecd48a9
[17:39:28] [luckperms-hikari connection closer/DEBUG] [me.lucko.luckperms.lib.hikari.pool.PoolBase]: luckperms-hikari - Closing connection me.lucko.luckperms.lib.mysql.jdbc.JDBC4Connection@43d5aef3: (connection has passed maxLifetime)
[17:39:28] [luckperms-hikari connection adder/DEBUG] [me.lucko.luckperms.lib.hikari.pool.HikariPool]: luckperms-hikari - Added connection me.lucko.luckperms.lib.mysql.jdbc.JDBC4Connection@1933eced
[17:39:28] [luckperms-hikari housekeeper/DEBUG] [me.lucko.luckperms.lib.hikari.pool.HikariPool]: luckperms-hikari - Pool stats (total=10, active=0, idle=10, waiting=0)
[17:39:34] [luckperms-hikari connection closer/DEBUG] [me.lucko.luckperms.lib.hikari.pool.PoolBase]: luckperms-hikari - Closing connection me.lucko.luckperms.lib.mysql.jdbc.JDBC4Connection@2e8a4c8: (connection has passed maxLifetime)
[17:39:34] [luckperms-hikari connection adder/DEBUG] [me.lucko.luckperms.lib.hikari.pool.HikariPool]: luckperms-hikari - Added connection me.lucko.luckperms.lib.mysql.jdbc.JDBC4Connection@33742a05
[17:39:58] [luckperms-hikari housekeeper/DEBUG] [me.lucko.luckperms.lib.hikari.pool.HikariPool]: luckperms-hikari - Pool stats (total=10, active=0, idle=10, waiting=0)
[17:40:10] [luckperms-hikari connection closer/DEBUG] [me.lucko.luckperms.lib.hikari.pool.PoolBase]: luckperms-hikari - Closing connection me.lucko.luckperms.lib.mysql.jdbc.JDBC4Connection@102ad2e9: (connection has passed maxLifetime)
[17:40:10] [luckperms-hikari connection adder/DEBUG] [me.lucko.luckperms.lib.hikari.pool.HikariPool]: luckperms-hikari - Added connection me.lucko.luckperms.lib.mysql.jdbc.JDBC4Connection@6922b685
Looks like permisison plugin was still active in its thread.
Ahh, curses. Does spark not show all threads? I know jstack or Visual VM do, which may be went using if this happens again. Otherwise I'm afraid it's quite hard to work out how the deadlock is happening.