Document Your Mod Mod

Document Your Mod Mod

606k Downloads

2.0.0 takes a long time to load past CraftTweaker

aaronhowser1 opened this issue · 18 comments

commented

image

commented

latest.log
Can confirm this. It even takes awhile to load a world for the first time.

commented

Yah, I had the same issue, but had blamed another mod for it.

commented

Wait this is what slowed my world gen too?
EDIT: this is ThatGuyWhoUsesXray

commented

I haven't experienced world gen lag or slower world gen. Just only when you load into the world. But not per dimension at least so loading into the nether for example is normal for me.

commented

Here is my log, had this when loading a world. Took almost a full minute on a pre-generated world, and my laptop usually does it in around 5 seconds in other modpacks.

latest.log

commented

How can I put it... those logs are very useless. They don't show anything wrong and the time it takes to load a world in the one by SonshineBoys is pretty normal considering the missing registry entries that are caused by cyclicmagic, whatever that is.
Having said that, I may have found an issue related to the slowness on world loading and that is the tooltips. I figure it attempts to create a tooltip for every single possible ItemStack on world load. And since I look up the configuration option on whether to do that every time, I see how that might be slow. I'll come up with a fix that doesn't reduce flexibility and I'll post a JAR with that fix in here in a few days, so that you can test and report whether the situation is now better or not.
About the original issue, so CraftTweaker taking several minutes to load, I have no idea how that could even be remotely related to us nor I see anything in the logs, so... that's still way in the dark.
For reference, at step 6, CraftTweaker does the following:

            RecipeBookClient.rebuildTable();
            if(CraftTweakerAPI.ENABLE_SEARCH_TREE_RECALCULATION) {
                minecraft.populateSearchTreeManager();
                ((SearchTree) minecraft.getSearchTreeManager().get(SearchTreeManager.ITEMS)).recalculate();
                ((SearchTree) minecraft.getSearchTreeManager().get(SearchTreeManager.RECIPES)).recalculate();
            }
            CraftTweakerAPI.logInfo("Fixed the RecipeBook");
commented

After days of looking around for what cyclic was trying to do, I realized something. I deleted Cyclic before that log was even posted. The fact something was searching for them proves of what the error was, as I had almost no scripts in my game and had already removed all references to Cyclic.

commented

First off, I'd like to say sorry for the huge delay I've come to this, but life and backlogs meant that this kept falling and falling behind other more important tasks. Nevertheless, the fix should be implemented and ready, though I'd like to have some more testing on different architectures. Of course, the fix will only affect you if you didn't enable debug tooltips: if those are enabled I can't help but let the mod do the work you've explicitly asked it to do 😛 .

At the bottom of this post there is a Zipped JAR (had to because GitHub: just unzip the file and inside you'll find the JAR). If you'd like to test whether you notice any improvement and report back, it would be very much appreciated. If this actually fixes everything, it'll be dropped as soon as possible onto an official build.

DocumentYourModMod-2.0.0+commit.878f8ed.jar.zip

commented

This one just makes my game crash every time for some reason

commented

Crash report please?

commented

And potentially move to its own issue

commented

Update from my side: cannot reproduce the crash, game loads fine and login time has improved, as evidenced by the logs. It's now down to 10 seconds on creation of a new world, which I consider pretty fast actually. Relevant log snippet is in the spoiler.

I'd like to mark this as fixed, since the initial CraftTweaker issue was a non-issue (at least I couldn't reproduce it on a brand new installation, so I assume it's some script taking longer) and the performance problems on login are fixed (as long as you don't have debug options enabled, but that's expected and normal behavior).

Spoiler
[14:46:29] [Server thread/INFO]: Starting integrated minecraft server version 1.12.2
[14:46:29] [Server thread/INFO]: Generating keypair
[14:46:29] [Server thread/INFO]: Injecting existing registry data into this server instance
[14:46:29] [Server thread/INFO]: Applying holder lookups
[14:46:29] [Server thread/INFO]: Holder lookups applied
[14:46:29] [Server thread/INFO]: Loading dimension 0 (New World) (net.minecraft.server.integrated.IntegratedServer@506a8579)
[14:46:30] [Server thread/INFO]: Loaded 488 advancements
[14:46:30] [Server thread/INFO]: Loading dimension -1 (New World) (net.minecraft.server.integrated.IntegratedServer@506a8579)
[14:46:30] [Server thread/INFO]: Loading dimension 1 (New World) (net.minecraft.server.integrated.IntegratedServer@506a8579)
[14:46:30] [Server thread/INFO]: Preparing start region for level 0
[14:46:31] [Server thread/INFO]: Preparing spawn area: 15%
[14:46:32] [Server thread/INFO]: Preparing spawn area: 29%
[14:46:33] [Server thread/INFO]: Preparing spawn area: 46%
[14:46:34] [Server thread/INFO]: Preparing spawn area: 67%
[14:46:35] [Server thread/INFO]: Preparing spawn area: 87%
[14:46:36] [Server thread/INFO]: Unloading dimension -1
[14:46:36] [Server thread/INFO]: Unloading dimension 1
[14:46:36] [Server thread/INFO]: Changing view distance to 12, from 10
[14:46:38] [Netty Local Client IO #0/INFO]: Server protocol version 2
[14:46:38] [Netty Server IO #1/INFO]: Client protocol version 2
[14:46:38] [Netty Server IO #1/INFO]: Client attempting to join with 15 mods : [SNIPPED]
[14:46:38] [Netty Server IO #1/INFO]: [net.thesilkminer.mvc.ModpackVersionChecker:onConnectRequest:70]: Connect request to CLIENT
[14:46:38] [Netty Local Client IO #0/INFO]: [net.thesilkminer.mvc.ModpackVersionChecker:onConnectRequest:70]: Connect request to SERVER
[14:46:38] [Netty Local Client IO #0/INFO]: [Netty Local Client IO #0] Client side modded connection established
[14:46:38] [Server thread/INFO]: [Server thread] Server side modded connection established
[14:46:38] [Server thread/INFO]: TheSilkMiner[local:E:0d14df35] logged in with entity id 1986 at (-246.5, 72.0, 169.5)
[14:46:38] [Server thread/INFO]: TheSilkMiner joined the game
[14:46:39] [Server thread/INFO]: Saving and pausing game...
[14:46:39] [Server thread/INFO]: Saving chunks for level 'New World'/overworld
commented

I've tested my pack with the Jar file supplied above. The loading has improved but it still takes a bit longer than normal with this mod installed. It now hangs at 6/7 once it loads Crafttweaker. Sits there for about 2 minutes. Which is an improvement over before. It hangs again when it gets to the "ModIDMapping" for about 40 seconds longer than normal.

Loading into a newly created world is only 5 seconds slower now compared to before. Which in-fact clocked in at about a whopping 15mins before. I'd say giving how much documentation this mod supplies the added load times during this recent test is mostly expected. So far so good. The game hasn't crashed for me like the other user.

If you want me to compare times, the updated jar file here, the normal one on curseforge and without it I can do that. It is definitely an improvement over before.

commented

First off, thank you for your feedback.

If you could do some time comparisons, it would be very helpful, yes, and thank you in advance.

About those two slowdowns, it seems there isn't much I can do. What happens is that Minecraft is asked to recalculate the entirety of the search tree (I assume something related to the creative tab where you can search, but I admit I am not that expert about this section of code). This happens in the following situations: a mod asks for it (like CT), Forge reaches the second to last step while loading, you login into a server (singleplayer counts).
The problem is that the recalculation that Mojang does not only creates a new ItemStack for every single item in the game three times (which is reasonable), but it asks for the tooltip almost every single time, which causes the event to fire and DYMM to do its calculations to add the documentation entry to the tooltip.
This means that, the bigger the modpack, the more times this event gets fired and the more lookups DYMM has to do. Most of the time this boils down to "no tooltip for this itemstack, return empty", and it's a very fast lookup, but it takes time of course. And that is probably responsible for the minute or so of loading that you encounter. On the positive side, I cache almost the entirety of the lookup for 5 minutes, meaning that you can exit and enter any world after the first cache (i.e. CT in your case) and the computation isn't done. Why 5 minutes only? Because most play sessions don't last only 5 minutes and keeping that data in memory is just a waste of RAM.

Now, could I make this faster? Probably. Is it worth it though? I don't really think so: the bottle-neck of the situation here is the debug situation, which isn't enabled in 99% of the cases.
Having said that, though, if you feel that this is too slow, I could look and see whether I could cache something else or try to see if there is a way to make it quicker, but I can't promise anything if so.

commented

Okay, so, I did some more testing and tweaked the code some more and I figure that the entire problem was solved.

Experiment description

To document my testing procedure, I used the very well-known pack "SevTech: Ages", with the following changes:

  • Smooth Font was removed
  • Better Chat was added
  • MVC (a personal mod: checks which pack version is being loaded at startup and that's it) was added
  • Optifine E3 was added
  • SEUS Renewed 1.0.0 was selected as a shader pack
  • The full set of Sphax resource pack was selected (containing "Sphax PureBDCraft 32x", "Sphax Music Pack", "Sphax Sound Pack", "Extra Optifine", "More 3D Blocks", "Technology", "Damaged Items", "SevTech 64x Sphax Patch" + a custom set of customizations for 20 blocks all around)

The entire pack was loaded from the start until the main menu was reached. Timing started at the first log message that was printed in latest.log and ended as soon as the main menu was loaded. I assigned 12 GB of RAM to the pack and let it roll with default GC arguments, basically letting Java handle the entire GC loading as it seemed fit. Also, my computer didn't experience any major workload during the loading of the pack, being focused only on the actual pack loading. Moreover, configurations settings for both DYMM and all the other mods were left untouched

I then rolled three tests in the following order:

  1. Pure SevTech: Ages with the above configuration
  2. SevTech: Ages with DYMM 2.0.0 added (version available on CurseForge)
  3. SevTech: Ages with DYMM 2.0.0 added (custom build that I'll link at the end of this post)

Results

Run Begin Timestamp End Timestamp Time Taken
1 11:04:40 11:09:46 00:05:06
2 11:14:07 11:23:24 00:09:17
3 11:26:27 11:31:56 00:05:29

Observations

Well, it is definitely noticeable how the CurseForge build of DYMM 2.0.0 has a huge impact on loading time, A huge impact I admit I hadn't thought about and I didn't even think was possible. Yet again the results are innegable. Something is definitely wrong there. And I also know the cause, which I'll outline in the below conclusions.
Having said that, you can also see how the performance improved version of DYMM barely impacts loading time, with a 30 seconds increase that, for the amount of documentation that it adds and the amount of processing it does, is surprisingly low for me. Yet again, I need to admit my PC is very high end and the only workload was MC so that could also be a reason, Nevertheless it's surely a huge improvement over CurseForge's DYMM 2.0.0.
Of course, this performance increase comes at a cost, which is RAM. Run 1 used at most 8 GB of RAM to reach the main menu, much like Run 2 (8.1 GB). Run 3 instead skyrocketed at a whopping 8.6 GB during ModIdMapping, before falling back down to the normal 8.1 GB before reaching the main menu. This isn't unexpected at all, but it is surely a concern. The reason will be described in the fix.

Conclusions

It's my personal belief that such an improvement is very important in a mod, making the load time go from 4 minutes to barely 30 seconds. Yet again, the amount of RAM used is also a concern, especially because not a lot of people have a lot to spare with big modpacks. But at the same time, garbage collection is also able to handle it. More details in the description of the fix.
All in all, I'd consider this case closed and I'd like to know the other people's opinion on this.

The Fix

What DYMM 2.0.0 did was keeping a cache of ItemStacks and DocumentationEntry-s, meaning that repeated loading of those items could be speed up significantly, since they don't have to be loaded every time, but they are stored in memory for a brief amount of time. To help with RAM, DYMM also performed periodic Garbage Collection of such cache, particularly every 500 Documentation Entries and 50 ItemStacks. This is fine-ish in Vanilla, but it's a huge hit in modded because ItemStacks get created and removed all the time and being able to create only 50 of them meant that the cache kept being filled and then emptied. This takes up a lot of CPU cycles, and that is what caused the issues.
The fix is basically to remove this limit and let everything be handled automatically. This is why the results showed an increase in RAM with 8.6 GBs being touched: those 500 MBs were cache entries that were created, added to the cache, and then emptied a few seconds later. Yet again, this doesn't mean that DYMM will always fill up half a gigabyte with entries: the library we are using for the cache is smart enough to notice when memory is low and it will start evicting entries to avoid overfilling. In the worst case scenario, the cache will do the same job that DYMM 2.0.0 did, so 500 entries and 50 stacks being loaded at all times. Meaning: more memory = faster loading, not enough memory available = slower loading. This behavior is common to all modded MC.
The real requirements this mod has, in the end, is 100 MBs more to store the registry and the entries, which is pretty lightweight.

Another solution

Another solution could be to reintroduce the RAM limits with much higher tolerances, e.g. around 5 thousand stacks and 1 thousand entries, though this could reintroduce some issues for even bigger modpacks. I'd like some input on this other idea.

Basically the question is: how much RAM/performance balance do we want to keep?
This attachment is all "performance", the CurseForge build is all "RAM", and there is no easy way to do "in-between": the in-between for a modpack may be one thing and for another may be another. Would you prefer if there were a configuration option to limit it? If so, to which defaults should it be set?

Attachments

DocumentYourModMod-2.0.0+commit.unknown.jar.zip (as always, zipped JAR, so you need to extract it)

commented

Interesting results. I didn't have the time yet to do my comparisons in my pack. But I was also gonna run it on a much weaker machine with a Hard Drive. My family and I play on a pack I created in our local home server. All their computers except for mine are still running Hard Drives. So their load times were always much longer than mine to begin with. I'll try out the 2nd Jar you attached when I return from work on my PC. Then I'll do the comparisons if possible.

As for the question about RAM/Performance. The balance I keep for my family's computers is maxing out the RAM for the pack to 6GBs. The Pack was made to run with that in mind since most of their computers only has 8GBs. As a configuration option, I don't think I'm the right person to make that call. But If it's not extremely difficult enough, you could have a config option for it. Though I'm sure most people would want speed over anything else. As most modpacks takes awhile to load as they are.

I'll try to get back to you with this when I can. Thank you for taking the time to investigate this strange issue.

commented

Thank you so much for your work on fixing this... I know it took a long time and am very grateful for how in-depth you went for a solution.

EDIT: Yah, my world previously took ab 1 min to load, now it takes 7 seconds.

commented

Hopefully fixed, will be available in the next version
Feel free to reopen if you encounter issues after the update will be pushed out