Game freezes in takeOverSlotOccupiedByRemovedItem when using crafting terminal
andrewjbennett opened this issue · 12 comments
Describe the bug
When I'm using the wireless crafting terminal (this happens with both the standard and wireless terminals), if I want to search for something different I type Ctrl+A to select the current text, then type something else and it replaces the text with the new thing.
If I start my new search with a #, the game freezes, eventually leading to "An internal error occurred in your connection", dropping me from the server I'm playing on.
Looking at jstack when the game freezes, the render thread is actively doing a lot of work, with the top entry for ae2 code being:
appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem([email protected]/Repo.java:267)
(I've put the full stack trace for the render thread below)
I'm playing the ATM7 mod pack, on a server.
How to reproduce the bug
- Open the wireless crafting terminal
- Type something in the search bar
- Press
Ctrl+Ato select the text - Type
#to start searching by tag
(note: there's potentially a shorter way to reproduce this, but given that it freezes my game and thus takes several minutes between attempts, I haven't tried to narrow it down further; I can reproduce the problem with the previous steps 100% of the time)
Expected behavior
You're able to continue typing something, and it searches for whatever you type
Additional details
"Render thread" #1 prio=10 os_prio=0 cpu=7124563.77ms elapsed=8550.83s tid=0x00007f42b8028d90 nid=0x230d23 runnable [0x00007f42be0ba000]
java.lang.Thread.State: RUNNABLE
at com.google.common.collect.HashBiMap.seekByKey([email protected]/HashBiMap.java:240)
at com.google.common.collect.HashBiMap.containsKey([email protected]/HashBiMap.java:262)
at appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem([email protected]/Repo.java:267)
at appeng.client.gui.me.common.Repo.updateView([email protected]/Repo.java:156)
at appeng.client.gui.me.common.Repo.handleUpdate([email protected]/Repo.java:103)
at appeng.core.sync.packets.MEInventoryUpdatePacket.clientPacketData([email protected]/MEInventoryUpdatePacket.java:287)
at appeng.core.sync.network.ClientPacketHandler.onPacketData([email protected]/ClientPacketHandler.java:37)
at appeng.core.sync.network.NetworkHandler.lambda$clientPacket$7([email protected]/NetworkHandler.java:99)
at appeng.core.sync.network.NetworkHandler$$Lambda$55743/0x0000000806053b60.run([email protected]/Unknown Source)
at net.minecraftforge.network.NetworkEvent$Context.enqueueWork([email protected]/NetworkEvent.java:213)
at appeng.core.sync.network.NetworkHandler.clientPacket([email protected]/NetworkHandler.java:99)
at net.minecraftforge.eventbus.ASMEventHandler_2869_NetworkHandler_clientPacket_ServerCustomPayloadEvent.invoke(.dynamic)
at net.minecraftforge.eventbus.ASMEventHandler.invoke([email protected]/ASMEventHandler.java:85)
at net.minecraftforge.eventbus.EventBus$$Lambda$4278/0x0000000800e5d0f8.invoke([email protected]/Unknown Source)
at net.minecraftforge.eventbus.EventBus.post([email protected]/EventBus.java:302)
at net.minecraftforge.eventbus.EventBus.post([email protected]/EventBus.java:283)
at net.minecraftforge.network.NetworkInstance.dispatch([email protected]/NetworkInstance.java:68)
at net.minecraftforge.network.NetworkHooks.lambda$onCustomPayload$1([email protected]/NetworkHooks.java:78)
at net.minecraftforge.network.NetworkHooks$$Lambda$49532/0x00000008058064a0.apply([email protected]/Unknown Source)
at java.util.Optional.map([email protected]/Optional.java:260)
at net.minecraftforge.network.NetworkHooks.onCustomPayload([email protected]/NetworkHooks.java:78)
at net.minecraft.client.multiplayer.ClientPacketListener.m_7413_([email protected]/ClientPacketListener.java:1824)
at net.minecraft.network.protocol.game.ClientboundCustomPayloadPacket.m_5797_([email protected]/ClientboundCustomPayloadPacket.java:57)
at net.minecraft.network.protocol.game.ClientboundCustomPayloadPacket.m_5797_([email protected]/ClientboundCustomPayloadPacket.java:7)
at net.minecraft.network.protocol.PacketUtils.m_131356_([email protected]/PacketUtils.java:22)
at net.minecraft.network.protocol.PacketUtils$$Lambda$49877/0x000000080585a828.run([email protected]/Unknown Source)
at net.minecraft.util.thread.BlockableEventLoop.m_6367_([email protected]/BlockableEventLoop.java:157)
at net.minecraft.util.thread.ReentrantBlockableEventLoop.m_6367_([email protected]/ReentrantBlockableEventLoop.java:23)
at net.minecraft.util.thread.BlockableEventLoop.m_7245_([email protected]/BlockableEventLoop.java:131)
at net.minecraft.util.thread.BlockableEventLoop.m_18699_([email protected]/BlockableEventLoop.java:116)
at net.minecraft.client.Minecraft.m_91383_([email protected]/Minecraft.java:1015)
at net.minecraft.client.Minecraft.m_91374_([email protected]/Minecraft.java:665)
at net.minecraft.client.main.Main.main([email protected]/Main.java:205)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0([email protected]/Native Method)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke([email protected]/NativeMethodAccessorImpl.java:77)
at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke([email protected]/DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke([email protected]/Method.java:568)
at net.minecraftforge.fml.loading.targets.CommonClientLaunchHandler.lambda$launchService$0([email protected]/CommonClientLaunchHandler.java:31)
at net.minecraftforge.fml.loading.targets.CommonClientLaunchHandler$$Lambda$864/0x00000008005a1e60.call([email protected]/Unknown Source)
at cpw.mods.modlauncher.LaunchServiceHandlerDecorator.launch([email protected]/LaunchServiceHandlerDecorator.java:37)
at cpw.mods.modlauncher.LaunchServiceHandler.launch([email protected]/LaunchServiceHandler.java:53)
at cpw.mods.modlauncher.LaunchServiceHandler.launch([email protected]/LaunchServiceHandler.java:71)
at cpw.mods.modlauncher.Launcher.run([email protected]/Launcher.java:106)
at cpw.mods.modlauncher.Launcher.main([email protected]/Launcher.java:77)
at cpw.mods.modlauncher.BootstrapLaunchConsumer.accept([email protected]/BootstrapLaunchConsumer.java:26)
at cpw.mods.modlauncher.BootstrapLaunchConsumer.accept([email protected]/BootstrapLaunchConsumer.java:23)
at cpw.mods.bootstraplauncher.BootstrapLauncher.main([email protected]/BootstrapLauncher.java:149)
Full jstack: https://gist.github.com/andrewjbennett/da4a22c854635a029fe7f848ae584033
Note: I haven't been able to trigger a crash while the problem is happening (presumably because it's not responding enough to realise I've pressed F3+C), but I've triggered one after getting the internal connection error, which hopefully will help.
The problem was also happening on the previous versions of AE2 that I was running (11.6.1-beta, 11.7.0, now 11.7.4), I updated to the latest version to see whether the problem was fixed (it's not).
$ grep takeOverSlot jstack*
jstack-2023-06-06-23:32:28: at appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem([email protected]/Repo.java:265)
jstack-2023-06-06-23:32:30: at appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem([email protected]/Repo.java:265)
jstack-2023-06-06-23:32:31: at appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem([email protected]/Repo.java:267)
jstack-2023-06-06-23:32:32: at appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem([email protected]/Repo.java:265)
jstack-2023-06-06-23:32:33: at appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem([email protected]/Repo.java:265)
jstack-2023-06-09-22:48:56: at appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem([email protected]/Repo.java:267)
jstack-2023-06-12-17:43:13: at appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem([email protected]/Repo.java:265)
jstack-2023-06-12-17:43:16: at appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem([email protected]/Repo.java:265)
jstack-2023-06-12-17:43:46: at appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem([email protected]/Repo.java:267)
jstack-2023-06-14-22:23:40: at appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem([email protected]/Repo.java:267)
Which minecraft version are you using?
1.18
On which mod loaders does it happen?
Forge
Crash log
https://gist.github.com/andrewjbennett/b053034a38d29852cc2ea3d8337699ae
I'm experimenting with various things to see what does / doesn't cause it to freeze. If I remove all of the storage cells from my drives the freeze doesn't happen, I'm now trying to narrow down whether it's certain types of cells or just having a lot of them.
I think it might be related to the number of unique items -- I have four ME DISK drives (the ones which hold an unlimited number of types of items, rather than just 63 types), I've split the items ~equally between two of them, and have two more that just have a few items in them. If I have either one of the two half-full drives it doesn't freeze, but if I have both of the half-full drives it does freeze.
If I have only the two ME DISK drives and none of my other drives (mostly 256k ME item storage cells, it doesn't crash. I have about 24 256k ME item storage cells in total, if I add 12 of them to the system it doesn't freeze (but does spend maybe 5-10 seconds in takeOverSlotOccupiedByRemovedItem), but if I add 14 of them it does freeze.
The more drives/items I add before trying to reproduce the problem, the longer it spends (in the takeOverSlot function), but it seems like it's hitting some sort of tipping point after which it can no longer recover (12 storage cells takes 5-10 seconds, 14 storage cells takes long enough that it drops me from the server)
I'll have a look, do you know offhand of some examples? (so I can search within the mods I'm using, rather than looking up every mod)
One that might be doing dodgy things is ModernFix, its description is "Egregious, yet effective performance improvements for modern minecraft". I'll try removing it and seeing whether I can still reproduce the problem (the game is restarting now with the mod removed, but loading the game takes a while)
BTW, further experimentation with disconnecting various parts of my network: if I have just the drives and nothing else it's fine; looking at one section of dense cables I have, if I have the lime one attached it freezes, but if I break the lime one (and leave the others attached) it's fine:
My lime cable is connected to three things, one is a storage bus which is a bit hectic: it's connected to a netherite chest (from sophisticated storage), which has compacting upgrades, and has ingots/blocks coming in and getting compacted (uranium ingots to uranium blocks, unobtainium nuggets to ingots). That said, disconnecting the storage bus (and nearby exporter) still lets me reproduce the freeze, once this freeze has recovered I'll check what the third connection is, the third connection is to an ME P2P tunnel which is connected to a single piece of dense cable, with no other connections. If I remove the ME P2P tunnel (so nothing connected to the lime cable) too it's fine, if I add the storage bus back it freezes again (so having nothing connected is fine, having just the ME P2P tunnel is not fine, having just the storage bus is not fine, having both is not fine)
The method you see the "freeze" in is updating the local state of the terminal in response to an update packet from the server (so something in your storage changed). The current tooling makes it hard to know if this is a lockup because of a single update or if it's happening due to thousands of updates...
Sophisticated storage has chests? I love the backpacks.... :-P
Can you estimate how many unique items you actually have shown in your terminal? Rough estimate is enough.
As an extremely rough estimate, I'd say probably about 5000-6000ish?
I counted out 100 then 200 then 300 rows, then extrapolated the total number of rows based on the scrollbar positions (probably around 600 ish), and multiplied by 9 items per row.
That should not be a problem. Are you using any performance mods that promise to use threads for something?
The current tooling makes it hard to know if this is a lockup because of a single update or if it's happening due to thousands of updates...
I would guess (but can't confirm) that it's due to a lot of updates, here are some sequential jstacks:
"Render thread" #1 prio=10 os_prio=0 cpu=822813.56ms elapsed=1225.21s tid=0x00007f82fc028d90 nid=0x27e4af runnable [0x00007f8300f95000]
java.lang.Thread.State: RUNNABLE
at com.google.common.collect.HashBiMap.seekByKey([email protected]/HashBiMap.java:240)
at com.google.common.collect.HashBiMap.containsKey([email protected]/HashBiMap.java:262)
at appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem([email protected]/Repo.java:267)
at appeng.client.gui.me.common.Repo.updateView([email protected]/Repo.java:156)
---
"Render thread" #1 prio=10 os_prio=0 cpu=823893.91ms elapsed=1226.32s tid=0x00007f82fc028d90 nid=0x27e4af runnable [0x00007f8300f95000]
java.lang.Thread.State: RUNNABLE
at appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem([email protected]/Repo.java:265)
at appeng.client.gui.me.common.Repo.updateView([email protected]/Repo.java:156)
---
"Render thread" #1 prio=10 os_prio=0 cpu=824929.26ms elapsed=1227.37s tid=0x00007f82fc028d90 nid=0x27e4af runnable [0x00007f8300f95000]
java.lang.Thread.State: RUNNABLE
at com.google.common.collect.HashBiMap.seekByKey([email protected]/HashBiMap.java:240)
at com.google.common.collect.HashBiMap.containsKey([email protected]/HashBiMap.java:262)
at appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem([email protected]/Repo.java:267)
---
"Render thread" #1 prio=10 os_prio=0 cpu=825925.39ms elapsed=1228.38s tid=0x00007f82fc028d90 nid=0x27e4af runnable [0x00007f8300f95000]
java.lang.Thread.State: RUNNABLE
at appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem([email protected]/Repo.java:265)
at appeng.client.gui.me.common.Repo.updateView([email protected]/Repo.java:156)
at appeng.client.gui.me.common.Repo.handleUpdate([email protected]/Repo.java:103)
So it is at least looping through multiple slots, but based on this I can't tell whether it's just looping through slots within the function call, or calling the function multiple times.
It's interesting that this is a side effect of the "don't move items around while paused" code (but it makes sense, typing # requires holding down shift, I'll check whether just holding down shift triggers it) -- just holding down shift doesn't trigger it, just typing # doesn't trigger it, I need to explicitly select the current text (with ctrl+a, haven't tested selecting with the mouse yet) then hold down shift then type #, just holding down shift with text selected doesn't trigger it.
Would it be possible to do something like add a config option to get it to skip checking for empty slots and just append? (
Applied-Energistics-2/src/main/java/appeng/client/gui/me/common/Repo.java
Lines 155 to 161 in b338557
Sophisticated storage has chests? I love the backpacks.... :-P
I know right? They're great. You can use mostly the same upgrades for them, I can't live without the stacking upgrades (so you can fit thousands of one item in one slot and thus have one slot per item type, makes chests so much more tidy)
BTW, with ModernFix disabled I can still reproduce the problem.
So it is at least looping through multiple slots, but based on this I can't tell whether it's just looping through slots within the function call, or calling the function multiple times.
I'll see if I can test this out with a debugger tomorrow, I've been doing some horrible things with attaching gdb to my java minecraft process.
Oh that's a VERY good point, I didn't even think about holding shift causing this. I'll take another look at the code.
The logic for putting incoming items into unused slots is quite fast.
Can you please run a spark client-side profile? (/sparkc command) that includes a few secondds of you holding shift?
With shift held down: https://spark.lucko.me/v6wj5S4zI9
Without shift held down: https://spark.lucko.me/hq3dlECGor
Both profiles were the same except for holding shift: I started recording the profile, then opened the wireless crafting terminal, and scrolled down to the bottom (so that I'd be able to see things move about). For the first profile, I held down shift for 5-10 seconds then stopped, then held it down again for a few seconds then stopped etc. For the second profile I did everything the same except for holding shift (so just sat there doing nothing).
With shift held down, it's spending a lot of time in takeOverSlotOccupiedByRemovedItem():
Without shift held down it doesn't spend any time in that function (obviously), but it's spending more time on rendering:
Ah, and here's a profile of me triggering the freeze but for a short enough duration that it didn't drop me from the server (I pressed escape a bunch of times immediately after triggering the freeze, and maybe one of those managed to make it through and got it to close the wireless terminal?) : https://spark.lucko.me/icduNAUkNi
I also took a profile in an external tool and triggered the full freeze (since I can't get the sparkc profile if it drops me from the server, afaik) which showed that function using 89% of the CPU
The most sampled method was boolean appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem(GridInventoryEntry, List), with 16.7 % of the maximum possible samples for 16/6/2023, 5:23:33.000 pm – 5:24:03 pm, and 88.7 % of the actual samples.
The methods that used the most CPU are:
appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem(GridInventoryEntry, List) (76.2 % of samples) 16/6/2023, 5:22:18.000 pm – 5:22:48 pm
appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem(GridInventoryEntry, List) (88.7 % of samples) 16/6/2023, 5:23:33.000 pm – 5:24:03 pm
The most common stack trace was:
at boolean appeng.client.gui.me.common.Repo.takeOverSlotOccupiedByRemovedItem(appeng.menu.me.common.GridInventoryEntry, java.util.List)
at void appeng.client.gui.me.common.Repo.updateView()
at void appeng.client.gui.me.common.Repo.handleUpdate(boolean, java.util.List)
at void appeng.core.sync.packets.MEInventoryUpdatePacket.clientPacketData(net.minecraft.world.entity.player.Player)
at void appeng.core.sync.network.ClientPacketHandler.onPacketData(net.minecraft.network.PacketListener, net.minecraft.network.FriendlyByteBuf, net.minecraft.world.entity.player.Player)
at void appeng.core.sync.network.NetworkHandler.lambda$clientPacket$7(net.minecraft.network.PacketListener, net.minecraftforge.network.NetworkEvent$ServerCustomPayloadEvent)
at void appeng.core.sync.network.NetworkHandler$$Lambda$55817+0x0000000805145c00.1124780418.run() at java.util.concurrent.CompletableFuture net.minecraftforge.network.NetworkEvent$Context.enqueueWork(java.lang.Runnable)
at void appeng.core.sync.network.NetworkHandler.clientPacket(net.minecraftforge.network.NetworkEvent$ServerCustomPayloadEvent)
at void net.minecraftforge.eventbus.ASMEventHandler_2868_NetworkHandler_clientPacket_ServerCustomPayloadEvent.invoke(net.minecraftforge.eventbus.api.Event)
at void net.minecraftforge.eventbus.ASMEventHandler.invoke(net.minecraftforge.eventbus.api.Event)
at void net.minecraftforge.eventbus.EventBus$$Lambda$4278+0x0000000800e5b1c0.1479893809.invoke(net.minecraftforge.eventbus.api.IEventListener, net.minecraftforge.eventbus.api.Event)
at boolean net.minecraftforge.eventbus.EventBus.post(net.minecraftforge.eventbus.api.Event, net.minecraftforge.eventbus.api.IEventBusInvokeDispatcher) at boolean net.minecraftforge.eventbus.EventBus.post(net.minecraftforge.eventbus.api.Event)
at boolean net.minecraftforge.network.NetworkInstance.dispatch(net.minecraftforge.network.NetworkDirection, net.minecraftforge.network.ICustomPacket, net.minecraft.network.Connection)
at java.lang.Boolean net.minecraftforge.network.NetworkHooks.lambda$onCustomPayload$1(net.minecraftforge.network.ICustomPacket, net.minecraft.network.Connection, net.minecraftforge.network.NetworkInstance)
at java.lang.Object net.minecraftforge.network.NetworkHooks$$Lambda$49488+0x00000008057b6f90.382649813.apply(java.lang.Object) at java.util.Optional java.util.Optional.map(java.util.function.Function)
at boolean net.minecraftforge.network.NetworkHooks.onCustomPayload(net.minecraftforge.network.ICustomPacket, net.minecraft.network.Connection)
at void net.minecraft.client.multiplayer.ClientPacketListener.m_7413_(net.minecraft.network.protocol.game.ClientboundCustomPayloadPacket)
at void net.minecraft.network.protocol.game.ClientboundCustomPayloadPacket.m_5797_(net.minecraft.network.protocol.game.ClientGamePacketListener)
at void net.minecraft.network.protocol.game.ClientboundCustomPayloadPacket.m_5797_(net.minecraft.network.PacketListener)
at void net.minecraft.network.protocol.PacketUtils.m_131356_(net.minecraft.network.PacketListener, net.minecraft.network.protocol.Packet)
at void net.minecraft.network.protocol.PacketUtils$$Lambda$49833+0x000000080580fa18.1287154018.run()
at void net.minecraft.util.thread.BlockableEventLoop.m_6367_(java.lang.Runnable)
at void net.minecraft.util.thread.ReentrantBlockableEventLoop.m_6367_(java.lang.Runnable)
at boolean net.minecraft.util.thread.BlockableEventLoop.m_7245_()
at void net.minecraft.util.thread.BlockableEventLoop.m_18699_()
at void net.minecraft.client.Minecraft.m_91383_(boolean)
at void net.minecraft.client.Minecraft.m_91374_()
at void net.minecraft.client.main.Main.main(java.lang.String[])
at java.lang.Object jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.lang.reflect.Method, java.lang.Object, java.lang.Object[])
at java.lang.Object jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.lang.Object, java.lang.Object[])
at java.lang.Object jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.lang.Object, java.lang.Object[])
at java.lang.Object java.lang.reflect.Method.invoke(java.lang.Object, java.lang.Object[])
at java.lang.Void net.minecraftforge.fml.loading.targets.CommonClientLaunchHandler.lambda$launchService$0(java.lang.ModuleLayer, java.lang.String[])
at java.lang.Object net.minecraftforge.fml.loading.targets.CommonClientLaunchHandler$$Lambda$865+0x00000008005a8200.1432888450.call()
at void cpw.mods.modlauncher.LaunchServiceHandlerDecorator.launch(java.lang.String[], java.lang.ModuleLayer)
at void cpw.mods.modlauncher.LaunchServiceHandler.launch(java.lang.String, java.lang.String[], java.lang.ModuleLayer, cpw.mods.modlauncher.TransformingClassLoader, cpw.mods.modlauncher.LaunchPluginHandler)
at void cpw.mods.modlauncher.LaunchServiceHandler.launch(cpw.mods.modlauncher.ArgumentHandler, java.lang.ModuleLayer, cpw.mods.modlauncher.TransformingClassLoader, cpw.mods.modlauncher.LaunchPluginHandler)
at void cpw.mods.modlauncher.Launcher.run(java.lang.String[])
at void cpw.mods.modlauncher.Launcher.main(java.lang.String[])
at void cpw.mods.modlauncher.BootstrapLaunchConsumer.accept(java.lang.String[])
at void cpw.mods.modlauncher.BootstrapLaunchConsumer.accept(java.lang.Object)
at void cpw.mods.bootstraplauncher.BootstrapLauncher.main(java.lang.String[])