Unexpected tick load from auto crafting tables
esotericist opened this issue · 7 comments
So I was troubleshooting some reduced TPS issues on my server using Lag Goggles, and to my surprise some of the highest offenders were auto-crafting tables that, at the time of the sampling, were all idle and empty.
As you can see in this screenshot, they range from 760 μS/t of processing to the highest at 835μS/t. Meaning just eight auto crafters alone are accounting for ~6 mS/t of processing time, while idle.
I'll be keeping an eye on other AW2 machines as I get them back online (I had to tear down my original base aside from the auto-crafters, and am setting things up again)
So I am not really sure what lag goggles show you there. I have just tried putting about 20,000 auto crafting tables in my world and I haven't seen anything that would stand out. Yes my tick time went up to 17 ms spent on tick, but that's pretty understandable to see with anything that has to check if it has something to do with every tick and that has a little more complicated logic to check than a furnace (auto crafting table has to check if its inventory has enough items for the current recipe and if the output inventory can hold the items crafted)
Is there anything specific about the recipes set in these? And do you get the same issue if you don't have any recipe set?
My apologies for the incomplete explanation.
There's nine auto-crafting tables in that screenshot (actually in total, this was where I was testing the build and hadn't made any anywhere else). Eight of them have ore shrub recipes (single ore berry in the top-left corner of crafting grid to produce a single nugget), the ninth had no recipe.
The eight tables with recipes were the ones consuming the 760 μS/t + of processing time despite at the time of profiling all having empty inventories (thus no actual work to do). The ninth, with no recipe only consumed 1 μS/t of processing time.
As points of comparison, an incomplete list of observed values in the same profiling session (that is, within the same 30 second sample period):
- AW2 mobs are consistently using between 30 and 50 μS/t (and this has held true more or less since the start of the server, including with hostile worldgen NPCs. I have occasionally seen over 50 μS/t, but only when trying to pathfind over a long distance, and that's perfectly understandable.) Even the workers who were explicitly set to check for work in all eight enabled auto crafters to them were still below 50 μS/t. (As was the courier who had nothing to give each of the inventories due to nothing to pull from the source inventory)
- In the background on the left you can barely make out two red cubes. They are a Botania hopperhock (26 μS/t) and solegnolia (23 μS/t) with essentially nothing to do (no entities within range).
- Thermal Expansion crafters, while a) possessing a recipe, b) fully filled with both materials and energy, and c) with their output slots full because their destination was also full, were accounting for 120 to 180 μS/t each.
- A single vanilla hopper, with a full inventory and full target inventory, was consuming about 160 μS/t, and vanilla hoppers are known absent mod interference to make multiple attempts per tick to insert items into a full inventory (despite generally not being much point trying after the first failure within the same tick).
- As an amusing outlier, a single backlogged Embers item pipe was consuming over 2000 μS/t, but embers item pipes in their current implementation are known to be even more prone to excessive re-attempts within a tick than vanilla hoppers (and have many other issues aside). Embers pipes have consequently been banned from the server, until such a time as the current maintainer of Embers can manage to correct their behavior.
Hopefully this is more useful information to you than my earlier post, and helps explain what my perspective was at the time of reporting.
So, I spent some time trying to replicate the problem in a minimal instance, like you asked. Kept getting 1 μS/t (or nothing, as essentially no measurable load) by way of lag goggles for the auto crafting stations whether they had a recipe or not, whether they had power or not (I made a rows for each of the possibilities with like 20 crafting tables each).
I went so far as to programmatically induce 12,000 recipes for wooden planks. No change.
I tried replicating the work conditions: added workers, courier trying to interact with the stations with empty inventory: no change.
Then I realized there was one factor that didn't require the entirety of my full mod pack to reproduce: I remembered being able to see the energy levels with the One Probe, and I knew that it didn't have RF for the One Probe to measure without Redstone Flux present.
I added the RedstoneFlux library, and The One Probe. Suddenly, I could measure a difference in CPU consumption with lag goggles between the ones with recipes and the ones without recipes: ~9-10 μS/t and 1 μS/t (or nothing) respectively.
Removed The One Probe: back to 1 μS/t.
Removed redstone flux, re-added the one probe, back up to measurable performance impact.
Somehow, what I'm experiencing is connected to the One Probe, but only with the auto crafting tables that have recipes. Just having inventory (I put a stack of logs into a machine with no recipe) isn't enough to do it.
I thought maybe somehow the One Probe might be querying the crafting station in a fashion that causes it to re-query which recipe it's using, so I re-added my brute-force recipe script, then changed one of the auto crafting stations to use the last recipe JEI lists. This gets a different increased value (in that instance, 11μS/t instead of 9μS/t for the rest of the tables).
In the interests of seeing if I could make that worse, I adjusted my script to produce 102,442 additional oak plank recipes. At this point, I get a visible hitch when I edit the crafting grid of the crafting stations, and have 11 TPS, but even going to one of the later recipes, I still only see 11μS/t instead of 9μS/t. That turned out to be a red herring: even without the One Probe present, auto crafting stations that have a shaped recipe consume slightly more time per tick than those that have a shapeless recipe. (1μS/t vs 3μS/t in my test instance typically)
In any case: The One Probe is doing something to AW2 auto crafting stations. I'm not in a position to attempt to trace what exactly is happening in a dev environment, but hopefully this is enough for you to work with.
Mods used: ancientwarfare-1.12.2-2.6.1.298, codechickenlib-1.12.2-3.2.0.345, crafttweeaker2-1.12-4.1.9, jei_1.12.2-4.11.0.206, laggoggles-forge-1.12.2-4.1, nbtedit-0.7, theoneprobe-1.12-1.4.23, forge 2705
This is definitely more useful unfortunately I am still not able to recreate anything. I have setup 100 auto crafters with recipes mostly using ore shrubs and the world takes about 7 ms to update and I am sure plenty of that is taken by entities which I have running around. One thing you can possibly try is changing the recipes to something from vanilla just to see if perhaps there's a performance issue with those recipes you have there. But I doubt that. It's more likely that lag goggles somehow affects performance of the auto crafters as I have seen reports of slowness caused by AW blocks in the past which I wasn't able to confirm even when using huge numbers of those "slow" blocks and looking at performance in detail.
To be clear: The absolute values are not what matters here. They're going to vary from machine to machine, from mod pack to mod pack, and the act of profiling is inherently going to affect the values. Total tick time does change while profiling because of the invasive hooks necessary to precisely measure the impact of specific objects.
That said: while profiling will inflate the real wall-clock time consumed by objects per-tick, it will do it in a generally evenly distributed fashion. What you're looking at with this kind of tool is not 'absolute consumption' but 'relative consumption' (which makes my incomplete information in my initial post more embarassing). What matters here is the proportion: that each AW2 auto-crafter with no inventory contents was observed consuming roughly ~4-5 times the CPU time than a vanilla hopper with known tendency to over-attempt its task is meaningful, even if the exact values aren't comparable between instances.
I see a bit of a difference between TOP and not TOP as well, but profiling it I can't see anything remotely measurable on AW side. Sampler basically shows me that out of 830 seconds that I spent running the game there were about 2 ms spent in the tile entity code and that's a total time so including all the time from methods that the tile entity code calls. Now sampler may not be exactly accurate, but it also wouldn't completely hide an issue like this. So I still tend to think that Lag Goggles is for some reason reporting a false positive here.