[Issue] Typing a Chat Message Causes a Massive Lag Spike
cwenck opened this issue · 10 comments
Describe
Typing in chat creates a massive lag spike. The tick in which the messages are processed ends up lasting for (tens of seconds to multiple minutes). The time is getting progressively longer on our server.
Reproduce
Currently we have a world with a self propelling mining machine built with Create. The machine is being chunk loaded using 4 chunky turtles. Three of those turtles are attached to the miner itself, and are moved by Create, and the last turtle moves by itself. These are the only cc-tweaked computers or turtles that exist in the world. This miner has moved roughly 55,000 blocks and the issue seems to be getting worse the longer the world (and the miner) run.
Steps to reproduce the behavior:
- Make a self-propelling flying machine with Create.
- Attach a chunky turtle to the machine.
- I suspect any kind of turtle will do.
- Let the machine run for a long time.
- Try typing messages in chat and there should be a lag spike as the message is processed.
Suspected Cause
Profile when typing a chat message: https://spark.lucko.me/jImuCwBmBz
For context, I am a Java programmer, but I'm not a forge modder. Based on my understanding of the source code, this is what I think is causing the issue.
When a chat message is sent, it is handled by the Events class. Those event handlers then both call getTileEntities from the TileEntityList. In the case of my world, getTileEntities takes a very long time.
As far as I can tell, the TileEntityList is supposed to be a cache of tile entities relevant to advanced peripherals. If my understanding is correct, then in theory this should only have 4 entries for the 4 turtles in my world. Given how long the tick times are taking when processing messages, I suspect that this cache is instead growing without having entries properly removed. Not sure if this is a result of them being moved by Create or just that they have moved a large number of blocks.
Suggestions
Here are some suggestions. I'm not super aware of the intricacies of forge, but here are some options to optimize the getTileEntities call.
- Only subscribe to the server chat event once, and only iterate through the cache of tile entities once. Based on the type of tile entity then delegate to separate methods to handle it for either the turtles or the computers. This would remove one of those two calls to
getTileEntities. - Consider using a
Setinstead of aListfor the underlying data structure. See TileEntityList.java#L21. This would avoid the need to do contains checks when adding items to the cache. It would also make contains checks significantly faster with large numbers of entries. - It looks like
setTileEntityis a toggle for whether a tile entity block position should be included in the cache. If it is already in the cache, remove it. Otherwise, if it isn't in the cache add it. I would suggest switching this to two methodsaddTileEntityandremoveTileEntityto avoid accidentally removing a tile entity when trying to add it or vice versa, which should make it easier to ensure the cache is updated correctly. I think this would avoid the need for thesetTileEntitymethod with theforceparameter too.
There are a few potential issues with getTileEntities itself.
public List<TileEntity> getTileEntities(World world) {
List<TileEntity> list = new ArrayList<>();
for (BlockPos next : new ArrayList<>(getBlockPositions())) {
if (world.isAirBlock(next) || !world.isBlockLoaded(next))
setTileEntity(world, next); //No block here anymore.
if (world.getTileEntity(next) == null)
setTileEntity(world, next); //No tile entity here anymore.
list.add(world.getTileEntity(next));
}
return list;
}- It starts by iterating through the different block positions, but if
setTileEntityis called, then it needs to iterate through all of them again when it's performing the contains check insetTileEntityhere. This makes this a very expensive method to run if the cache is large since the check is O(n^2). - Even if the tile entity was removed from the list by the first if statement, it seems like it could potentially be re-added by the second if statement. This is not something I'm super familiar with, but it seems like it's reasonable that a block could be air and have the tile entity at that position be
nullat the same time. Since currently,setTileEntitytoggles whether the block position is in the cache. The net result is that the position that should have been removed twice instead remains in the cache. Finally, even if it was removed from the cache, it is still added to the final resultListto be returned, which seems like the wrong behavior.
Versions:
- Mod Pack (All the Mods 6): 1.6.1
- Forge version: 36.1.2
- AdvancedPeripherals version: 0.4.5b
Crashlog/log (Use https://paste.gg or https://pastebin.com to upload your crashlog/log)
This doesn't cause a crash.
The world where this is happening is pretty large (multiple GB), but I can potentially provide a copy if needed.
Even if the tile entity was removed from the list by the first if statement, it seems like it could potentially be re-added by the second if statement. This is not something I'm super familiar with, but it seems like it's reasonable that a block could be air and have the tile entity at that position be null at the same time
You're right, I will fix that.
Could you do /advancedperipherals debug and send me the output? You can click on the message.
It's a very very very long list. It's too big for pastebin, which apparently has a 512kb limit. Let me see if I can find an alternative to pastebin that will take it.
It was too big for pastemyst too. This isn't even all of it since the scrollback on the terminal where the server is being run is limited, but here it is. Turns out GitHub gists work: https://gist.githubusercontent.com/cwenck/61e3dd6156e692d71defd6fe9feac9e1/raw/3a61500e1db6073433648f43817fb3cdbbba82dc/gistfile1.txt
advancedperipherals-0.5.1b.zip
Could you try it with this build?
Unzip it before using.
Try to type more messages
Sorry, I meant that to mean that I will test it. It does look like entries are getting correctly removed now when a chat message is typed. The list goes down to something like this soon after a message:
[BlockPos{x=48505, y=79, z=-897}, BlockPos{x=54109, y=79, z=-897}, BlockPos{x=48514, y=78, z=-898}, BlockPos{x=54118, y=78, z=-898}, BlockPos{x=48516, y=78, z=-897}, BlockPos{x=54120, y=78, z=-897}, BlockPos{x=54109, y=79, z=-899}, BlockPos{x=48505, y=79, z=-899}]
There is one thing that will still potentially an issue though, although it's less problematic. I'm assuming the cache only gets cleared when a message is typed in chat, so it will still potentially build up to a larger than ideal amount given enough time without a message being sent.
For example, after leaving it alone for a little while without typing a message, it's now up to this:
[BlockPos{x=48505, y=79, z=-897}, BlockPos{x=54109, y=79, z=-897}, BlockPos{x=48514, y=78, z=-898}, BlockPos{x=54118, y=78, z=-898}, BlockPos{x=48516, y=78, z=-897}, BlockPos{x=54120, y=78, z=-897}, BlockPos{x=54109, y=79, z=-899}, BlockPos{x=48505, y=79, z=-899}, BlockPos{x=48506, y=79, z=-897}, BlockPos{x=54110, y=79, z=-897}, BlockPos{x=48515, y=78, z=-898}, BlockPos{x=54119, y=78, z=-898}, BlockPos{x=48517, y=78, z=-897}, BlockPos{x=54121, y=78, z=-897}, BlockPos{x=54110, y=79, z=-899}, BlockPos{x=48506, y=79, z=-899}, BlockPos{x=48507, y=79, z=-897}, BlockPos{x=54111, y=79, z=-897}, BlockPos{x=48516, y=78, z=-898}, BlockPos{x=54120, y=78, z=-898}, BlockPos{x=48518, y=78, z=-897}, BlockPos{x=54122, y=78, z=-897}, BlockPos{x=54111, y=79, z=-899}, BlockPos{x=48507, y=79, z=-899}, BlockPos{x=48508, y=79, z=-897}, BlockPos{x=54112, y=79, z=-897}, BlockPos{x=48517, y=78, z=-898}, BlockPos{x=54121, y=78, z=-898}, BlockPos{x=48519, y=78, z=-897}, BlockPos{x=54123, y=78, z=-897}, BlockPos{x=54112, y=79, z=-899}, BlockPos{x=48508, y=79, z=-899}, BlockPos{x=48509, y=79, z=-897}, BlockPos{x=54113, y=79, z=-897}, BlockPos{x=48518, y=78, z=-898}, BlockPos{x=54122, y=78, z=-898}, BlockPos{x=48520, y=78, z=-897}, BlockPos{x=54124, y=78, z=-897}, BlockPos{x=54113, y=79, z=-899}, BlockPos{x=48509, y=79, z=-899}, BlockPos{x=48510, y=79, z=-897}, BlockPos{x=54114, y=79, z=-897}, BlockPos{x=48519, y=78, z=-898}, BlockPos{x=54123, y=78, z=-898}, BlockPos{x=48521, y=78, z=-897}, BlockPos{x=54125, y=78, z=-897}, BlockPos{x=54114, y=79, z=-899}, BlockPos{x=48510, y=79, z=-899}, BlockPos{x=48511, y=79, z=-897}, BlockPos{x=54115, y=79, z=-897}, BlockPos{x=48520, y=78, z=-898}, BlockPos{x=54124, y=78, z=-898}, BlockPos{x=48522, y=78, z=-897}, BlockPos{x=54126, y=78, z=-897}, BlockPos{x=54115, y=79, z=-899}, BlockPos{x=48511, y=79, z=-899}, BlockPos{x=48512, y=79, z=-897}, BlockPos{x=54116, y=79, z=-897}, BlockPos{x=48521, y=78, z=-898}, BlockPos{x=54125, y=78, z=-898}, BlockPos{x=48523, y=78, z=-897}, BlockPos{x=54127, y=78, z=-897}, BlockPos{x=54116, y=79, z=-899}, BlockPos{x=48512, y=79, z=-899}, BlockPos{x=48513, y=79, z=-897}, BlockPos{x=54117, y=79, z=-897}, BlockPos{x=48522, y=78, z=-898}, BlockPos{x=54126, y=78, z=-898}, BlockPos{x=48524, y=78, z=-897}, BlockPos{x=54128, y=78, z=-897}, BlockPos{x=54117, y=79, z=-899}, BlockPos{x=48513, y=79, z=-899}, BlockPos{x=48514, y=79, z=-897}, BlockPos{x=54118, y=79, z=-897}, BlockPos{x=48523, y=78, z=-898}, BlockPos{x=54127, y=78, z=-898}, BlockPos{x=48525, y=78, z=-897}, BlockPos{x=54129, y=78, z=-897}, BlockPos{x=54118, y=79, z=-899}, BlockPos{x=48514, y=79, z=-899}, BlockPos{x=48515, y=79, z=-897}, BlockPos{x=54119, y=79, z=-897}, BlockPos{x=48524, y=78, z=-898}, BlockPos{x=54128, y=78, z=-898}, BlockPos{x=48526, y=78, z=-897}, BlockPos{x=54130, y=78, z=-897}, BlockPos{x=54119, y=79, z=-899}, BlockPos{x=48515, y=79, z=-899}, BlockPos{x=48516, y=79, z=-897}, BlockPos{x=54120, y=79, z=-897}, BlockPos{x=48525, y=78, z=-898}, BlockPos{x=54129, y=78, z=-898}, BlockPos{x=48527, y=78, z=-897}, BlockPos{x=54131, y=78, z=-897}, BlockPos{x=54120, y=79, z=-899}, BlockPos{x=48516, y=79, z=-899}, BlockPos{x=48517, y=79, z=-897}, BlockPos{x=54121, y=79, z=-897}, BlockPos{x=48526, y=78, z=-898}, BlockPos{x=54130, y=78, z=-898}, BlockPos{x=48528, y=78, z=-897}, BlockPos{x=54132, y=78, z=-897}, BlockPos{x=54121, y=79, z=-899}, BlockPos{x=48517, y=79, z=-899}, BlockPos{x=48518, y=79, z=-897}, BlockPos{x=54122, y=79, z=-897}, BlockPos{x=48527, y=78, z=-898}, BlockPos{x=54131, y=78, z=-898}, BlockPos{x=48529, y=78, z=-897}, BlockPos{x=54133, y=78, z=-897}, BlockPos{x=54122, y=79, z=-899}, BlockPos{x=48518, y=79, z=-899}, BlockPos{x=48519, y=79, z=-897}, BlockPos{x=54123, y=79, z=-897}, BlockPos{x=48528, y=78, z=-898}, BlockPos{x=54132, y=78, z=-898}, BlockPos{x=48530, y=78, z=-897}, BlockPos{x=54134, y=78, z=-897}, BlockPos{x=54123, y=79, z=-899}, BlockPos{x=48519, y=79, z=-899}, BlockPos{x=48520, y=79, z=-897}, BlockPos{x=54124, y=79, z=-897}, BlockPos{x=48529, y=78, z=-898}, BlockPos{x=54133, y=78, z=-898}, BlockPos{x=48531, y=78, z=-897}, BlockPos{x=54135, y=78, z=-897}, BlockPos{x=54124, y=79, z=-899}, BlockPos{x=48520, y=79, z=-899}, BlockPos{x=48521, y=79, z=-897}, BlockPos{x=54125, y=79, z=-897}, BlockPos{x=48530, y=78, z=-898}, BlockPos{x=54134, y=78, z=-898}, BlockPos{x=48532, y=78, z=-897}, BlockPos{x=54136, y=78, z=-897}, BlockPos{x=54125, y=79, z=-899}, BlockPos{x=48521, y=79, z=-899}, BlockPos{x=48522, y=79, z=-897}, BlockPos{x=54126, y=79, z=-897}, BlockPos{x=48531, y=78, z=-898}, BlockPos{x=54135, y=78, z=-898}, BlockPos{x=48533, y=78, z=-897}, BlockPos{x=54137, y=78, z=-897}, BlockPos{x=54126, y=79, z=-899}, BlockPos{x=48522, y=79, z=-899}, BlockPos{x=48523, y=79, z=-897}, BlockPos{x=54127, y=79, z=-897}, BlockPos{x=48532, y=78, z=-898}, BlockPos{x=54136, y=78, z=-898}, BlockPos{x=48534, y=78, z=-897}, BlockPos{x=54138, y=78, z=-897}, BlockPos{x=54127, y=79, z=-899}, BlockPos{x=48523, y=79, z=-899}, BlockPos{x=48524, y=79, z=-897}, BlockPos{x=54128, y=79, z=-897}, BlockPos{x=48533, y=78, z=-898}, BlockPos{x=54137, y=78, z=-898}, BlockPos{x=48535, y=78, z=-897}, BlockPos{x=54139, y=78, z=-897}, BlockPos{x=54128, y=79, z=-899}, BlockPos{x=48524, y=79, z=-899}, BlockPos{x=48525, y=79, z=-897}, BlockPos{x=54129, y=79, z=-897}, BlockPos{x=48534, y=78, z=-898}, BlockPos{x=54138, y=78, z=-898}, BlockPos{x=48536, y=78, z=-897}, BlockPos{x=54140, y=78, z=-897}, BlockPos{x=54129, y=79, z=-899}, BlockPos{x=48525, y=79, z=-899}, BlockPos{x=48526, y=79, z=-897}, BlockPos{x=54130, y=79, z=-897}, BlockPos{x=48535, y=78, z=-898}, BlockPos{x=54139, y=78, z=-898}, BlockPos{x=48537, y=78, z=-897}, BlockPos{x=54141, y=78, z=-897}, BlockPos{x=54130, y=79, z=-899}, BlockPos{x=48526, y=79, z=-899}, BlockPos{x=48527, y=79, z=-897}, BlockPos{x=54131, y=79, z=-897}, BlockPos{x=54140, y=78, z=-898}, BlockPos{x=48536, y=78, z=-898}, BlockPos{x=54142, y=78, z=-897}, BlockPos{x=48538, y=78, z=-897}, BlockPos{x=54131, y=79, z=-899}, BlockPos{x=48527, y=79, z=-899}, BlockPos{x=48528, y=79, z=-897}, BlockPos{x=54132, y=79, z=-897}, BlockPos{x=48537, y=78, z=-898}, BlockPos{x=54141, y=78, z=-898}, BlockPos{x=48539, y=78, z=-897}, BlockPos{x=54143, y=78, z=-897}, BlockPos{x=54132, y=79, z=-899}, BlockPos{x=48528, y=79, z=-899}, BlockPos{x=48529, y=79, z=-897}, BlockPos{x=54133, y=79, z=-897}, BlockPos{x=48538, y=78, z=-898}, BlockPos{x=54142, y=78, z=-898}, BlockPos{x=48540, y=78, z=-897}, BlockPos{x=54144, y=78, z=-897}, BlockPos{x=54133, y=79, z=-899}, BlockPos{x=48529, y=79, z=-899}, BlockPos{x=48530, y=79, z=-897}, BlockPos{x=54134, y=79, z=-897}, BlockPos{x=48539, y=78, z=-898}, BlockPos{x=54143, y=78, z=-898}, BlockPos{x=48541, y=78, z=-897}, BlockPos{x=54145, y=78, z=-897}, BlockPos{x=54134, y=79, z=-899}, BlockPos{x=48530, y=79, z=-899}, BlockPos{x=48531, y=79, z=-897}, BlockPos{x=54135, y=79, z=-897}, BlockPos{x=48540, y=78, z=-898}, BlockPos{x=54144, y=78, z=-898}, BlockPos{x=48542, y=78, z=-897}, BlockPos{x=54146, y=78, z=-897}, BlockPos{x=54135, y=79, z=-899}, BlockPos{x=48531, y=79, z=-899}, BlockPos{x=48532, y=79, z=-897}, BlockPos{x=54136, y=79, z=-897}, BlockPos{x=48541, y=78, z=-898}, BlockPos{x=54145, y=78, z=-898}, BlockPos{x=48543, y=78, z=-897}, BlockPos{x=54147, y=78, z=-897}, BlockPos{x=54136, y=79, z=-899}, BlockPos{x=48532, y=79, z=-899}, BlockPos{x=48533, y=79, z=-897}, BlockPos{x=54137, y=79, z=-897}, BlockPos{x=48542, y=78, z=-898}, BlockPos{x=54146, y=78, z=-898}, BlockPos{x=48544, y=78, z=-897}, BlockPos{x=54148, y=78, z=-897}, BlockPos{x=54137, y=79, z=-899}, BlockPos{x=48533, y=79, z=-899}, BlockPos{x=48534, y=79, z=-897}, BlockPos{x=54138, y=79, z=-897}, BlockPos{x=48543, y=78, z=-898}, BlockPos{x=54147, y=78, z=-898}, BlockPos{x=48545, y=78, z=-897}, BlockPos{x=54149, y=78, z=-897}, BlockPos{x=54138, y=79, z=-899}, BlockPos{x=48534, y=79, z=-899}, BlockPos{x=48535, y=79, z=-897}]