MSPT graph in F3 shows wrong color for idle time
yugiohfag69-prog opened this issue · 8 comments
Bug Description
Hi there!
I've began to mod MC 1.21.1, Fabric 0.17.2, Java Eclipse Adoptium jdk-21.0.8.9-hotspot Win65 (idk if that helps but sometimes yes).
And noticed, if a game contains ModernFix (tried 2 versions 5.24.2 and 5.24.3 with different Fabric and Java versions) even without any other mods, the average TPS becomes ~50 after world creation settles down, which is absurd amount for ModernFix which has proven to be in a list of best optimization mods on par with Sodium nowadays.
Done it with and without Sodium installed (also tried different versions).
Happens after both creating new world or going to existing one.
Reproduction Steps
- Install (clean) Java 21 TLS
- Install (clean) MC 1.21.1
- Install Fabric loader 0.17.2
- Upload current version of ModernFix (may as well throw Sodium there, doesn't change behavior of issue but kinda default mod to have)
- Create new world
- Press F3+2 and watch TPS graph
Log File
It's strange nobody writes about this issue, so I might miss something.
Apologies in advance.
I'm not sure I understand your issue; regardless of positive, neutral, or negative performance effects and optimisation of this mod, TPS should always be limited to 20 no matter what. If your TPS graph is showing an upper bound that does not read as 20.0, then you've either run /tick rate <something that isn't 20>, a datapack has, or a mod has.
At 20 TPS, you will have 50 MSPT though. 50 ms per tick gives 20 ticks a second, with the graph showing red for tick processing time, and green as the rest of the time spent waiting (to maintain 20 TPS max). If the red part exceeds 50 ms, then the green (waiting) part won't happen because the tick will be taking >50 MSPT and therefore the TPS will be below 20 and the server should be catching up, not waiting.
AFAIK, there's nothing that modifies this behaviour in this mod, because this is just very core Vanilla mechanics that no mod usually touches. /tick rate and other mods/datapacks that explicitly aim at changing the tick rate are generally the only things that call on deviating from the assumed Vanilla mechanic of 20 TPS max (∴ 50 max MSPT) and if a tick takes <1,000÷TPS ms to process, wait, otherwise don't.
Understandable, thank you for the clear explanation!
But my graph with only ModernFix looks like this:
Does that mean waiting time for server is completely eliminated or does it do something else?
Also, usually high MSPS means few of the ticks stuck being processed, and if it rises high above screen means you wait some time for it to unlag.
So what's happening here?
Interesting stuff that I noticed too, no performance drops. So I might just misjudge some functionality of ModernFix which actually benefit me, sorry if that's the case and you have to explain technical stuff to a dum-dum.
To be fair, I'm far from professional or knowledgeable about Minecraft code and performance optimisation. I'm generally a little knowledgeable and interested in the technical, in-game side of Minecraft's game logic (I'm a technical Minecrafter not a mod dev :3)—so this is just what little knowledge I do have from my perspective.
Here's a quick 'n' nasty little (way too explicit and yappy) guide I made just now:
Also, usually high MSPS means few of the ticks stuck being processed, and if it rises high above screen means you wait some time for it to unlag.
You're right; I re-explained basically this at the end of the above graphic regarding the transparent parts of the graph. So yeah, if the graph goes over that white line, you're lagging for that tick so the game is catching up/"unlagging."
Scheduling phase info
I should note: For the beige scheduling phase,
- When the game is performing ideally, this phase is so negligible it either doesn't show up or shows up as a single pixel (1 ms out of that tick). I often don't see it on my server because it's dedicated to solely running Minecraft
-
When the game is running poorly, because of:
- Poor server hardware/little RAM/stuff like that
- Other programs on the server eating performance
- On laptops, power-saving/battery-preserving modes
- The Minecraft world having a ton of block events (e.g. Water flowing), Redstone, players, or other conventionally laggy stuff
- Other mods causing the above (e.g. modded blocks that do a lot of stuff (like Create machines, for example (I don't think Create does this btw just using it for an idea))) or being coded poorly and thus scheduling too much
- ModernFix may have a bug
(I can't repro., but I'm on a different MC version)and its ModernFix's fault for the above - A myriad of other stuff I'm nowhere near knowledgeable or skilled enough to understand, let alone diagnose
You usually only see a super beige graph when all of a sudden there's a lot of lag and the server's struggling but trying its best to catch up. Generally when it does this, the beige is all over the place.
The really weird thing is that your schedule phase is really consistent, trying to stay in 20 TPS. It's far from perfect (those few pixels above and below the white are beyond the margin of smooth tick rates (in a normal performance state in Vanilla this is generally perfectly flat, with no stray pixels)), but for a part of the graph that generally is a sign of things going horribly wrong, its notable how tame it is!?
Having just checked my game (1.21.8), I'm getting the same mostly-scheduling graph on the client, with no idles. My graph is completely flat, whilst yours jitters a lot more, but idk. Whatever I said above probably means nothing. I did notice, however, on my non-ModernFix server that there's no beige and it's all green too. Strange.
I am SO not qualified as to why this is. I'll also note how you have those spikes in your graph, and the transparent sprinting ticks too, so it's clear at those points there's some really laggy thing happening that stalls the server for a couple ticks for long enough it spends like the next 10 ticks catching up to smooth out.
Where those spikes come from and a LOT of unrelated but useful-for-optimisation information
Generally those spikes come from:
- Obvious moments in-game like if you flick a lever that runs some Redstone machine or crazy farm that causes a lot of lag very suddenly and then the server catches up
- Some datapack or command blocks running a bunch of
/forceloads or doing maths or (((no idea))) but it's doing a lot - Java's garbage collector: more RAM isn't more better. I don't know if you know much about the GC so I'll go through it in full (excruciating detail) in case this applies (so hopefully I can help you 😃):
[!NOTE]
Java allocates memory dynamically. You dedicate Java n GB of RAM. This dedicated memory is where Java puts its heap. The heap is where Java stores whatever needs to go to RAM: currently loaded textures, incoming and outgoing data packets, game info, chunk data, Minecraft code, etc (basically everything involved in running the game). The heap has two properties:
- Heap size: The amount of dedicated RAM you gave to Java. This is the space it'll do its working and storage of the above things I mentioned in. If you dedicate 4 GB of RAM to Minecraft, Java gets 4 GB of space to work with for storing textures, numbers, data, and whatever
- Allocated heap: The heap size is the RAM Minecraft/Java is actually using. This is the size of the actual data Java has stored in memory. If you give Java 4 GB, but there's only like 800 MB of textures and chunk data and whatever else Minecraft uses, then you'll have a 4 GB heap of which 800 MB is actually allocated/used
Now unlike other languages like C (where the programmer has to allocate memory to store numbers and textures and whatever data they need, then remember to free it up once they're done using it), Java has no such manual memory management. It's all dynamic.
What this means is that the programmer declares the values of data, and Java handles putting it somewhere, allocating the space to store that data, and allocating extra space to store data to keep track of that value.
Data that doesn't get called anymore gets flagged for deletion ("garbage"). It'd be really bad if every time a function ended or an object was abandoned Java went and de-allocated all of that data and keeping-track-of-it data and memory space. This is because code runs fast, and doing this for every single variable very single time it's no longer needed would use a ton of CPU!!!
The solution to this is the garbage collector: Java just flags the data as no longer needed, then just deletes it in a batch every time the used heap space starts to fill up with so much unused old data that the used heap space starts to encroach on the allocated heap (dedicated RAM).
This is still a tradeoff: Either thousands of little CPU-intensive moments to free up RAM—which adds up and makes the whole program constantly laggy or save all that CPU-intensive work for one big lag spike in return for a program that only lags when the garbage collector has to run.
The garbage collector, especially nowadays, is nowhere near as bad as it used to be, so there is a spike, but calling it a "lag spike" is a little extreme.More RAM isn't always more better
More RAM dedicated (aka larger heap) means Minecraft can store more chunks, HD textures, etc much easier and can run generally a little faster and more efficiently. However: this means there'll be more to clean up each GC run:
Allocating 1–2 GB to Minecraft means that, if the garbage collector ran at like 80% heap utilisation, and cleaned up like 50% of the heap (~400–800 MB of data), that'd be 400–800 MB worth of CPU processing and heap de-allocation work
Allocating 8–16 GB or crazier amounts if you have a beefy PC might sound like a good idea, right? Give Minecraft access to more of your good PC? Wrong. Using the above example of a GC run at 80% that clears 50% of the heap, that's now 6,400–12,800 MB of data cleaned up! That's a lot more work for the CPU to do, and on the server can make those massive MSPT spikes, and on the client the big frametime spikes.The GC is usually more noticeable on the client with the FPS lag spikes IMO.
So the more you allocate, the less often the GC will run, but the impact will go from unnoticeable to MASSIVE, QUICK.
If you have a ton of memory dedicated to your client/server, try reducing it. On a nice desktop, 1–4 GB is fine and can get you framerates of 1,000+ easy. On a server, even with 20–30 players, 8 GB is plenty too—you'd rather optimise the CPU impact of Villagers, Redstone, and players before you'd want to touch dedicated RAM; 6–8 GB for a server is still on the high end too, especially if you have single-digit player counts at any point in time.
So yeah, the spikes and slowdowns might be an issue for you? (Top-right of your F3 will show heap usage:)
It's quite common in Minecraft for many people to allocate more RAM thinking it'll do them better, when it doesn't.
If that alone isn't too helpful, you can also try swapping out the Minecraft Launcher JVM in your launch config with your own one, and using something like GraalVM's java/javaw JRE rather than the OpenJDK or Oracle ones (GraalVM has better memory management and optimisations that can provide a minor help).
Additionally you can try some launch flags to mess with your garbage collector, like using Shenandoah or G1GC (I think that's the default these days though) instead of the default GC or whatever and seeing what can help. For example, my client launch arguments are:
-Xmx4G -Xms4G -XX:+UnlockExperimentalVMOptions -XX:+UseG1GC -XX:G1NewSizePercent=20 -XX:G1ReservePercent=20 -XX:MaxGCPauseMillis=50 -XX:G1HeapRegionSize=32M
Now actually regarding this issue rather than general stuff:
The graph could be either:
- The beige graph is Vanilla behaviour as of some 1.21.x update. The green idle phase screenshot I got is therefore a product of how Servux (a server mod) sent the MSPT profiler info to my client.
But my graph with only ModernFix […]
If you are able to add/remove ModernFix and deduce that it _is_ ModernFix causing this, then this explanation CANNOT be the case. If so: - ModernFix is causing this, either by misreporting the profiler information, or by some other code change that causes a ton of scheduling
I should note that if ModernFix is causing this, and given I am actually able to reproduce this on a singleplayer local server:
Interesting stuff that I noticed too, no performance drops.
Given how consistent my graph appears, I think it's very possible this bug actually is valid (now I can repro. it), and there's no performance hit (just some internal error/misconfiguration/idk in the mod), and the more inconsistent graph you're getting is probably due to external lag-making factors. I think.
I might just misjudge some functionality of ModernFix which actually benefit me, sorry if that's the case and you have to explain technical stuff to a dum-dum.
I'm really unqualified as to what's causing this, too, so you and I both can only diagnose it so far.
My final and best diagnosis I can come up with is this:
Idle tick phase replaced with redundant tick scheduling spam
Reproduced on Minecraft versions: 1.21.1, 1.21.8
Did NOT occur on Minecraft version: 1.21
Tested on ModernFix versions: v5.20.4-beta.51+mc1.21.7.a724, v5.24.2, v5.24.3
Fabric: 0.17.2
Java: Eclipse Adoptium jdk-21.0.8.9, OpenJDK GraalVM CE 21.0.2+13.1
There is no performance impact to all of this scheduling, suggesting that a bunch of null events are being scheduled for the next tick, which don't run any code, and thus don't create a performance impact
- This might be caused by a bad mixin/reimplementation of Mojang's idle tick phase code somewhere where ModernFix is injected, or
- This might be good ModernFix code that broke with Mojang updating some tick mechanics which the (alleged) mixin is breaking because it's using idle tick logic that was valid for an older version of Minecraft—probably 1.21 and before
@toydotgame First of all, this is an impressively well-written guide, you should turn it into a blog post or something more indexable than a random comment on a GitHub issue. 😛
Using this information I was able to figure out what I think is going on here.
- The MSPT is not actually 50. If you look at the top-left of F3 it shows much lower numbers when the game is idling (at least on 1.21.1, didn't check 1.21.8). Therefore, this is just a visual issue with the graph.
- There is an optimization (
mixin.perf.fix_loop_spin_waiting) that fixes MC-183518. I originally wrote that logic for 1.20.1 where the TPS graph in F3 renders different information (none of the extra fancy colors it has now). The patch seems to have the side effect of making idle time count as tick scheduling rather than idle time. This is probably an easy fix, I just need to look into how the new graph works. - That mixin should actually be removed after 1.21.1, as vanilla already has the same patch. This will fix the issue on 1.21.8.
Oh yeah, would you look at that! Thanks for finding and figuring out exactly what mixin it was! Disabling it, restarting, and bam:
The MSPT is not actually 50. If you look at the top-left of F3 it shows much lower numbers when the game is idling (at least on 1.21.1, didn't check 1.21.8). Therefore, this is just a visual issue with the graph.
Good call; I noted that in my image that the min/avg/max info lines exclude idle time explicitly. Therefore I have no idea why I later went on to assume that the tick time was this magical consistent 50 ms that never faulted—and for some reason didn't read either screenshot of the graphs twice to realise that, indeed, the ticks arent 50 ms lmao. 😭
First of all, this is an impressively well-written guide, you should turn it into a blog post or something more indexable than a random comment on a GitHub issue. 😛
Thanks!! I do write a blog, and honestly I was thinking about doing that once I had resized the canvas in GIMP for about the 5th time to add more slop. I also believe it's important to preach the as-common-as-dirt-in-optimisation-spaces-but-not-well-known-to-general-Minecrafters adage of More RAM ≠ More Better. I've already written naïvely about Minecraft server internal workings way above my experience level before (😛), so honestly I think it'd be useful to make a nicer-looking and not hacked-together-in-GIMP reference guide and explanation of the profiler.