Justenoughitems: Loading times terrible slower (seems to be stuck) with JEI 412

[MatthiasMann]

Uisng forge-1.10.2-12.18.3.2234
jei_1.10.2-3.14.6.412.jar
CraftTweaker-1.10.2-3.0.20.jar
EnderIO-1.10.2-3.1.171.jar
OptiFine_1.10.2_HD_U_D6.jar

The loading is now nearly stuck at "LoadComplete" with mezz.jei.plugins.vanilla.ingredients.ItemStackRenderer.getTooltip(ItemStackRenderer.java:43) calling the tooltip handlers of the various mods which at some point invoke both:
org.lwjgl.input.Keyboard.isCreated()
org.lwjgl.input.Keyboard.isKeyDown(Keyboard.java:404)

which in turn wait on the LWJGL lock hold by the splash screen thread. This caused my loading time to extend ~15 minutes for that part alone.

https://gist.github.com/MatthiasMann/4085eab55653d498119f6ed310391db9

[MatthiasMann]

This only seems to happen when V-Sync and Optifine is enabled.
With V-sync disabled or without Optifine loading proceeds fast.

[sp614x]

Relevant part of the stack trace:

"Client thread" #1 prio=10 os_prio=2 tid=0x000000000213a000 nid=0xc0c waiting for monitor entry [0x00000000023bb000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at org.lwjgl.input.Keyboard.isCreated(Keyboard.java:344)
==>     - waiting to lock <0x000000070a815ba8> (a java.lang.Object)
        at minetweaker.mc1102.ForgeEventHandler.onItemTooltip(ForgeEventHandler.java:46)
        at net.minecraftforge.fml.common.eventhandler.ASMEventHandler_185_ForgeEventHandler_onItemTooltip_ItemTooltipEvent.invoke(.dynamic)
        at net.minecraftforge.fml.common.eventhandler.ASMEventHandler.invoke(ASMEventHandler.java:90)
        at net.minecraftforge.fml.common.eventhandler.EventBus.post(EventBus.java:185)
        at net.minecraftforge.event.ForgeEventFactory.onItemTooltip(ForgeEventFactory.java:265)
        at net.minecraft.item.ItemStack.func_82840_a(ItemStack.java:794)
        at mezz.jei.plugins.vanilla.ingredients.ItemStackRenderer.getTooltip(ItemStackRenderer.java:43)
        at mezz.jei.plugins.vanilla.ingredients.ItemStackRenderer.getTooltip(ItemStackRenderer.java:21)
        at mezz.jei.IngredientInformation.getTooltipString(IngredientInformation.java:28)
        at mezz.jei.util.IngredientListElement.<init>(IngredientListElement.java:56)
        at mezz.jei.util.IngredientListElement.create(IngredientListElement.java:31)
        at mezz.jei.IngredientBaseListFactory.addToBaseList(IngredientBaseListFactory.java:56)
        at mezz.jei.IngredientBaseListFactory.create(IngredientBaseListFactory.java:38)
        at mezz.jei.ItemFilter.<init>(ItemFilter.java:31)
        at mezz.jei.JeiStarter.start(JeiStarter.java:57)
        at mezz.jei.ProxyCommonClient.loadComplete(ProxyCommonClient.java:111)
        at mezz.jei.JustEnoughItems.loadComplete(JustEnoughItems.java:53)

it is waiting for the Forge SplashProgress thread:

"Thread-7" #22 prio=10 os_prio=2 tid=0x000000001dd19000 nid=0xdcc runnable [0x000000002869f000]
   java.lang.Thread.State: RUNNABLE
        at org.lwjgl.opengl.WindowsContextImplementation.nSwapBuffers(Native Method)
        at org.lwjgl.opengl.WindowsContextImplementation.swapBuffers(WindowsContextImplementation.java:70)
        - locked <0x0000000710901d20> (a org.lwjgl.opengl.ContextGL)
        at org.lwjgl.opengl.ContextGL.swapBuffers(ContextGL.java:175)
        at org.lwjgl.opengl.DrawableGL.swapBuffers(DrawableGL.java:90)
        at org.lwjgl.opengl.Display.swapBuffers(Display.java:618)
        - eliminated <0x000000070a815ba8> (a java.lang.Object)
        at org.lwjgl.opengl.Display.update(Display.java:646)
==>     - locked <0x000000070a815ba8> (a java.lang.Object)
        at org.lwjgl.opengl.Display.update(Display.java:628)
        at net.minecraftforge.fml.client.SplashProgress$3.run(SplashProgress.java:351)
        at java.lang.Thread.run(Thread.java:745)

[sp614x]

When VSync is enabled the Forge SplashProgress thread blocks for 16ms on each frame waiting on the monitor to finish the current frame.
This seems to throttle the JEI initialization which calls ItemStack.getTooltip() which indirectly calls MineTweaker's onItemTooltip() which calls Keyboard.isCreated() which needs the LWJGL global lock, which is being held by the SplashThread.

Several things may be wrong:

• the Forge SplashThread is running without a FPS limit, so it is constantly getting and releasing the LWJGL global lock: https://github.com/MinecraftForge/FML/blob/master/src/main/java/net/minecraftforge/fml/client/SplashProgress.java#L254. This is delaying the initialization for all mods that need the LWJGL lock and it is also unnecessarily loading the CPU during initialization. Adding a Thread.sleep(20) in the loop should fix both problems.
• JEI is creating all possible tooltips during the initialization. This is probably not needed, the tooltip can be created when it has to be shown, no need to cache it.
• MineTweaker is checking for Keyboard.isCreated() in onItemTooltip(), no idea if really needed
• OptiFine may be enabling the VSync too early, while the splash screen is still visible. Usually this is irrelevant, only in this case there is a race between the SplashThread and the tooltip creation for the LWJGL lock.

[mezz]

Thanks for looking into it, I think we came to the same conclusions more or less.

Here's what I found when looking more into each of your bullets:

1. the end of that while loop has a Display.sync(100):
   https://github.com/MinecraftForge/FML/blob/master/src/main/java/net/minecraftforge/fml/client/SplashProgress.java#L352
   That should work like your sleep idea, from what I understand it just calculates how long to sleep in order to maintain 100 fps. Maybe this does not work well with VSync?

2. JEI creates all the tooltips so that it can search them instantly later. It only takes a couple seconds to gather them all (when this bug is not active) so startup is a good time to do it I think.

3. The Keyboard.isCreated check is strange, but it grabs the same global lock as Keyboard.isKeyDown so I don't think it would cause more problems than any other tooltip handler that checks for Shift. It might be used while running automated tests or something like that.

4. Is Optifine's Vsync different from the VSync option built into Minecraft?

[sp614x]

OptiFine is not changing the VSync, it uses the same and only possible implementation as vanilla:
Display.setVSyncEnabled(this.gameSettings.enableVsync);.
Maybe OptiFine enables the VSync earlier, not sure.
Vanilla is only calling Display.sync() when the FPS limiter is set. It is possible that the combination of VSync + Display.sync() is the problem.
Display.sync(): https://github.com/LWJGL/lwjgl/blob/master/src/java/org/lwjgl/opengl/Display.java#L410
Sync.sync(): https://github.com/LWJGL/lwjgl/blob/master/src/java/org/lwjgl/opengl/Sync.java#L65
The SplashThread is calling Display.sync() from another thread (not the main thread), this may also be a multithreaded issue.

[Fogrits]

Well, now without VSync my screen tears a lot. This issue happens even with NVIDIA's VSync setting on the control panel.

[sp614x]

The Display.sync(100) is not effective when VSync is enabled.
What happens in this case is:

1. VSync uses monitor refresh, which is usually 60 FPS = frame time 16 ms.
2. 100 FPS = frame time 10 ms
3. Display.ipdate() blocks via VSync for 16 ms: https://github.com/MinecraftForge/FML/blob/master/src/main/java/net/minecraftforge/fml/client/SplashProgress.java#L346
4. Display.sync(100) checks the elapsed time since last sync(). The time is 16ms, which is more than sync(100) should wait (10ms) so it does not wait.
5. On the next loop the same repeats, Display.ipdate() blocks for 16ms, then sync(100) does not wait because more than 10ms are passed, and so on.

Effectively all the time is spent in Display.ipdate() which is waiting for the VSync.
Replacing the Display.sync(100) with Thread.wait(30) should fix the problem.

[XxZajoZzO]

https://forum.feed-the-beast.com/threads/stuck-on-loading-6-7-jei-3-0-7.218851/
This also happens in sky factory 3 in the newest pack update.

[mezz]

Thanks @sp614x that looks right. I tested it and got it to work correctly.
Made a PR here https://github.com/MinecraftForge/MinecraftForge/pull/3725

[sp614x]

Yes, Thread.sleep() is the correct method, wait() was a typo.

[luffykick]

here is a fix for NEI slow loading... https://forum.feed-the-beast.com/threads/stuck-on-loading-6-7-jei-3-0-7.218851/

[cpw]

@sp614x Display.sync is a noop. Changing it does nothing. The problem is that the _necessary_ call to Display.update is taking the global GL lock, and the underlying display driver is imposing an FPS limiter so Display.update doesn't return for a long time. Anything trying to query Keyboard.isKeyDown (and lots of other input state operations) during the time the lock is taken will block until the lock returns. Removing the sync call and replacing it with something shittier isn't going to change this behaviour at all.

The problem is the driver imposing Vsync by blocking the call to Display.update() from returning - holding that gl global lock for WAY longer than it should.

There's no trivial fix except disabling the driver level vsync (which may or may not be the same thing as the result of Display.setVsyncEnabled(true)) or disabling the splash screen.

[MatthiasMann]

@cpw The issue at hand is that a Vsync refresh rate of 60 Hz (~16.6ms) is much longer than the sleep time for Display.sync(100) - which causes Display.sync to be a no-op. Which in turn means the loop is spending all time in Display.update().

With the explicit sleep call the loop will spend some guaranteed time outside of Display.update() and as such also outside the LWJGL lock. That way the other threads can make progress.

[enricotagliavini]

@cpw about driver VSync: it could also not be the driver to force the VSync, it could also be the desktop compositor. The only way to get a tear free Desktop rendering is to have a compositor and this might force VSync, rightfully so. That's my case: I have vsync disabled in MC, I don't need it in MC, my desktop compositor is doing its job and is ensuring the frame to be displayed at once.

So disabling VSync is not an option as it breaks tear free desktop / tear free gaming. It might not be trivial, but if adding some forced sleep time to the thread mitigates the issue until the non-trivial fix is ready it would be nice. Telling people to disable splash to have normal game load times is not going to work (can you imaging the rage on reddit? ;) )

[mezz]

We're working on it now.

[mezz]

Fixed by cpw here: https://github.com/MinecraftForge/MinecraftForge/commit/03d7eaae23fa21710cdc6c6fc9d9c98e5fa14755

[enricotagliavini]

Many thanks that was quick! Will try the new Forge release this evening alongside new JEI.

[sp614x]

@cpw IMHO the fix is overengineered. Trying to detect if VSync is enabled (guess), then switching to a different mode, counting frames, checking update times, etc.
A simple Thread.sleep(30) should have been enough, the splash screen does not need 60 fps, it can work perfectly fine with 10-15 fps.

[MatthiasMann]

Exactly my thoughts - there are so many things which can go wrong with the new code.
In the earlier JEI version with the progress bar the Vsync time was most likely spend inside one of the OpenGL rendering calls. And I have seen this in my own OpenGL applications too. This can change depending on what is rendered. So the actual behavior might change after the initial measurement.

[LukaPix]

I think im experiencing the same issue but im not really sure, game gets stuck at Finishing up/Loading complete.
Also JEI takes considerably long and doesnt finish up it's building ingredient filter after 2 hours...
One of my cpu core is permanently at 70% load so it in fact is doing something...

Im trying to load 340 mods but everything works fine exept this...
I tried disabling VSync and its doesn't seem to have any effect whatsoever..
I can't disable Optifine or even with my quite powerful PC performance will be abominable...

[mezz]

@LukaPix This specific issue is related to VSync and the FML loading screen. Please try removing optifine just to confirm if it is part of the problem, and then open a new issue.

[maximumsomething]

If you're coming here from Google and you still have this issue, minimizing the window will make it load faster.