Astral Sorcery

Astral Sorcery

63M Downloads

Heavy CPU utilization in concert with corail tombstone

JoshuaRowePhantom opened this issue ยท 9 comments

commented

I filed this issue with corail tombstone, they were particularly unhelpful. I'm following up here. Tombstone does some onCheckDiscretion logic that attempts to get an enchantment level, which ends up in astral sorcery, as per the spark trace linked below.

This is in AllTheMods 1.16.5, Astral Sorcery 1.16.5-1.13.12.

https://spark.lucko.me/gx0oUElePI
AllTheMods/ATM-6#2411
Corail31/tombstone_lite#17

commented

Addition: I would strongly recommend using something more accurate than Spark at this point, like a visual-vm profile instead. Spark is good as a starting point, but it's not very numerically accurate but it requires less setup and provides less impact on the program being profiled.

I'm not seeing one large spike source, so Spark is unlikely to prove more useful at this point. A vanilla server could very much look like this distribution with similar volumes of entities, and I say that from experience.

commented

Uh, while that's a shitty response from that dev, can you provide a bit more information on what's the issue you're seeing? With the exception of it running against sheep, looks like most of those onCheckDiscretions are hundredths of a percent of the server thread over that time period (and sheep are 2.x%, which is likely due to volume of sheep in the world), the remaining 3.5% comes back to the AnimalEntity passive class.

Looking through bookmarked instances, I'm not seeing where this should really be a concern for overall load on the server. If you're viewing by the "Sources" section, instead of "all", you're not seeing the full picture really well.

Honestly as the full trace is less than 8 seconds (7800ms) you aren't getting a very good reference frame either way. I would recommend running a much longer one, over a few minutes, to get an accurate look. Some things that are problems may not be showing up in a trace that short, and other things will be inflated. 10% isn't enough to be a focus for a lag spike if you were attempting to isolate the issue to that, and even so, mekanism eats far more tick time as an aggregate whole, though not even that looks to be a major problem since it's so widespread across so many instances for both "sources" of server load.

commented

Thanks. I'll capture a longer trace and upload later today. I've captured about 10 traces with the same data.

I'm not sure I understand why you're saying there's only a few hundredths of a percent in onCheckDiscretions:

image

This part of the trace seems to pretty clearly show DynamicEnchantmentHelper.getNewEnchantmentLevel using ~7.8% of CPU. It shows up in both the sources view and the all view. Maybe I'm misinterpreting this?

I'm not diagnosing lag spikes in single ticks, I'm diagnosing overall server performance. I agree something is bad with my server, though it's just itzg/minecraft-server:java11 docker image running ATM 1.16.5 on a 3.6GHz machine (though in a VM), so I don't know what I'd be doing that others aren't. I see that Mekanism is using lots of CPU as well, was heading down that path too.

commented

Later tonight I'll try a different profiler.

commented

It's a misinterpretation based on the display mode, yes. Change from Source to All and it'll make more sense when it's broken out fully.

Also, it's not 7.8% of CPU, because that view doesn't include all the time for vanilla MC itself. It's a total of 5200-ish ms out of the 800ms of the trace.

Some perf stats out of the VM would also be good to have to see, along with what it's spec'd resource limits for that VM are.

Also...why java11? Please use Java8 for MC 1.16.

commented

I tried java11 in the hopes it would resolve perf. Back to java8. Thanks for the definitive information.

Looking at "All", I find multiple paths that all resolve down to getNewEnchantmentLevel. For example, sheep:

image

eidolon:zombie_brute was causing the same issue. The "sources" view merely seems to have coalesced the calls originating from corail tombstone into a summation showing ~7.8% of CPU added up across all callers. I suspect this trace is accurate in -that- sense, though perhaps there's something deeper going on.

Looking further into the call stack, I find this:

image

I -think- that something that might be happening here is I'm using IPv6, and that getPlayerIP code might be more expensive in IPv6. Maybe there's a better detection mechanism available?

commented

That's still really small resource utilization, and not something I would consider worth being concerned over.

commented

I don't understand the statement about being strikingly small. Across all callstacks, astral sorcery getNewEnchantmentLevel is using ~7.7% of CPU. Even on less heavily loaded minecraft server, it looks like a little optimization in that area might save a few megatons of carbon per year across the planet :-).

commented

Even if every download of this mod in its history was actively running on a server that was up 24/7/365 at the same time, it still wouldn't have that much impact over the course of a year.

My house is run almost entirely on LED lights. If I took a 7 second snapshot of my power consumption with all electronics in the house off outside of the refrigerator, it could look like a significant portion of power usage in my household if neither the A/C compressor for the HVAC or the fridge were running at the time. Doesn't change that when the HVAC kicks on or if I fire up a computer to play a game that power usage is literally a footnote insignificant enough to the thrown out statistically.

Context matters.