Extremely high memory usage with Harder Ores

[Haggle1996]

I'm trying to figure out what can be done about RAM with COG and @Draco18s Harder Ores. At the moment, I suggest to my players to use 6GB of RAM or more allocated to minecraft. However, they go out of memory after a bit of world exploration. Pregenerating a world doesn't work either, for the same reason.

Specifically, it seems like COG never releases any memory. It just grows constantly. I'm using the latest code built directly from your GitHub repository, but this has always been an issue since the CurseForge version.

[lawremi]

Just to clarify, was it not leaking memory prior to the CurseForge version? Does this happen without HarderOres?

[Haggle1996]

Yes, the memory usage has never changed...I don't know if it's 'leaking' or just not releasing RAM. I will test without Harder Ores, using your vanilla generation, and report back.

[Haggle1996]

In a test setup without harder ores (so it's only generating AE2 certus and vanilla), it still 'leaks' memory, but at a significantly lower rate. The memory usage never goes down or releases until it runs out. Granted, I got to 140,000ish chunks before going out of memory, versus the few thousand I get with Harder Ores.

[lawremi]

Is this only happening on the clients or also the server? An obvious culprit would be the debug mode. It saves information on every distribution instance and never releases it. Perhaps this information is somehow being saved even when debugging mode is disabled. But none of that code has been changed since I took over maintenance years ago, so I'm not sure this is a new issue. Are you sure this just started with the curse version? Thanks for your testing.

[Haggle1996]

Both clients and servers. I've only been using COG since it was made available on CurseForge. I build and distribute directly from your GitHub repository.

[Draco18s]

Hard Ours would cause COG to use more memory than without, due to the largeness of the distributions, but it shouldn't be holding memory alive itself.

[Haggle1996]

Yes, I don't believe the problem is caused by Harder Ores, just exacerbated by all the ore distributions. I'm just trying to get to the bottom of why ore generation is not releasing memory, which is the source of not being able to pregenerate maps in my pack.

[lawremi]

Well, with just COG and HarderOres installed, I'm unable to exhaust memory. Using F3, memory usage drops with each garbage collection. The base level does vary and does seem to increase a bit. But I've explored thousands of chunks topping out under 2GB.

I used a memory debugger and the memory usage of COG was quite small, almost entirely in the structure cache (which it needs to place distributions before they are populated). The cache is purged with each generation, dropping older entries. The /cogClear debugging console command clears the cache completely, so you might try that to see if it helps.

[Haggle1996]

Testing now. Out of question, which version of Java are you on?

[lawremi]

Tested with both openjdk 1.7 and Oracle 1.8.

[Haggle1996]

Okay. I can repeat this now with a minimal modset of Java8, Forge 1614, COG, Harder Ores, and HardLib (and AdminCommandsToolbox to make pregeneration easy, but I can replicate regardless).

With clean configuration files, load up and pregenerate using /pregenspawn 100 (which causes AdminCommandsToolbox to pregenerate 40,000 chunks). Memory hovers between 900MB and 1.2GB, and pregeneration completes successfully.

Next, open up HarderOres.cfg and change the following values to '2' to force generation:

ores {
    # These settings should be auto-detected during worldgen and act as an override.
    # 0 will prevent flowers, 2 will enforce (set automatically), 1 is default. [range: 0 ~ 2, default: 1]
    I:OreExists...=1

    #  [range: 0 ~ 2, default: 1]
    I:OreExistsAluminum=1

    #  [range: 0 ~ 2, default: 1]
    I:OreExistsCadmium=1

    #  [range: 0 ~ 2, default: 1]
    I:OreExistsCopper=1

    #  [range: 0 ~ 2, default: 1]
    I:OreExistsFlourite=1

    #  [range: 0 ~ 2, default: 1]
    I:OreExistsLead=1

    #  [range: 0 ~ 2, default: 1]
    I:OreExistsNickel=1

    #  [range: 0 ~ 2, default: 1]
    I:OreExistsOsmium=1

    #  [range: 0 ~ 2, default: 1]
    I:OreExistsSilver=1

    #  [range: 0 ~ 2, default: 1]
    I:OreExistsThorium=1

    #  [range: 0 ~ 2, default: 1]
    I:OreExistsTin=1

    #  [range: 0 ~ 2, default: 1]
    I:OreExistsUranium=1

    #  [range: 0 ~ 2, default: 1]
    I:OreExistsZinc=1
}

Reload the game and start a new map. Execute /pregenspawn 100. Memory starts at about 900MB and slowly climbs until RAM is exhausted.

@Draco18s, It is my understanding that setting the above options to 2 forces their veins to spawn, regardless of the presence of mods that have those ores. This leads me to conclude that one or more vein definitions in the HarderExtraOres.xml file are causing the excessive memory leak.

I have neither tested yet if switching to vanilla generation for these ores solves the issue, nor tried to narrow down which one(s) may be at fault.

[Draco18s]

That doesn't force ores that forces the flowers. To force the ores you have to jiggle with the COG settings.

That, however, does narrow things down a bit.

My offhand guess is that it's having to allocate extra RAM for storing the ore counts (which are all 0 in this case, but it's still forced to save that 0 for every chunk) and memory isn't being released somehow (yes, my code unloads the data when chunks unload).

[Haggle1996]

I reloaded the heavy version of my pack with all the flower options above set to 0, and regenerated a well-known seed that exhausts 6GB of RAM after pregenerating about 1400 chunks. With the flower options set to 0, I made it almost 7000 chunks pregenerated before exhausting memory. I did note that vanilla flowers (redstone, iron, etc., still generate).

For kicks and giggles, I turned on your flower debugging. I now receive these errors spewing forth en masse in my latest.log (not fml-client-latest):

[14:31:56] [Client thread/INFO]: [CHAT] Pregenerating for dim 0 | X : [ -103 97 ] | Z : [ -104 96 ]
[14:32:01] [Client thread/INFO]: [CHAT] Generated 100 / 40000 chunks [ 0.25% ]
[14:32:01] [Server thread/ERROR]: "Silently" catching entity tracking error.
net.minecraft.util.ReportedException: Adding entity to track
    at net.minecraft.entity.EntityTracker.func_72785_a(EntityTracker.java:230) [mn.class:?]
    at cpw.mods.fml.common.registry.EntityRegistry.tryTrackingEntity(EntityRegistry.java:364) [EntityRegistry.class:?]
    at net.minecraft.entity.EntityTracker.func_72786_a(EntityTracker.java:61) [mn.class:?]
    at net.minecraft.world.WorldManager.func_72703_a(SourceFile:31) [mp.class:?]
    at net.minecraft.world.World.func_72923_a(World.java:1347) [ahb.class:?]
    at net.minecraft.world.WorldServer.func_72923_a(WorldServer.java:844) [mt.class:?]
    at net.minecraft.world.World.func_72868_a(World.java:3304) [ahb.class:?]
    at net.minecraft.world.chunk.Chunk.func_76631_c(Chunk.java:921) [apx.class:?]
    at net.minecraftforge.common.chunkio.ChunkIOProvider.callStage2(ChunkIOProvider.java:46) [ChunkIOProvider.class:?]
    at net.minecraftforge.common.chunkio.ChunkIOProvider.callStage2(ChunkIOProvider.java:12) [ChunkIOProvider.class:?]
    at net.minecraftforge.common.util.AsynchronousExecutor.skipQueue(AsynchronousExecutor.java:344) [AsynchronousExecutor.class:?]
    at net.minecraftforge.common.util.AsynchronousExecutor.getSkipQueue(AsynchronousExecutor.java:302) [AsynchronousExecutor.class:?]
    at net.minecraftforge.common.chunkio.ChunkIOExecutor.syncChunkLoad(ChunkIOExecutor.java:12) [ChunkIOExecutor.class:?]
    at net.minecraft.world.gen.ChunkProviderServer.loadChunk(ChunkProviderServer.java:126) [ms.class:?]
    at net.minecraft.world.gen.ChunkProviderServer.func_73158_c(ChunkProviderServer.java:101) [ms.class:?]
    at net.minecraft.world.gen.ChunkProviderServer.func_73154_d(ChunkProviderServer.java:199) [ms.class:?]
    at net.minecraft.world.World.func_72964_e(World.java:419) [ahb.class:?]
    at com.draco18s.ores.util.OreDataHooks.saveData(OreDataHooks.java:176) [OreDataHooks.class:?]
    at com.draco18s.ores.OresEventHandler.chunkSave(OresEventHandler.java:314) [OresEventHandler.class:?]
    at cpw.mods.fml.common.eventhandler.ASMEventHandler_1610_OresEventHandler_chunkSave_Save.invoke(.dynamic) [?:?]
    at cpw.mods.fml.common.eventhandler.ASMEventHandler.invoke(ASMEventHandler.java:54) [ASMEventHandler.class:?]
    at cpw.mods.fml.common.eventhandler.EventBus.post(EventBus.java:140) [EventBus.class:?]
    at net.minecraft.world.chunk.storage.AnvilChunkLoader.func_75816_a(AnvilChunkLoader.java:198) [aqk.class:?]
    at net.minecraft.world.gen.ChunkProviderServer.func_73242_b(ChunkProviderServer.java:256) [ms.class:?]
    at sun.reflect.GeneratedMethodAccessor40.invoke(Unknown Source) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_74]
    at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_74]
    at mcp.mobius.pregen.exec.PregenExec.exec(PregenExec.java:188) [PregenExec.class:?]
    at mcp.mobius.pregen.TickHandler.foo(TickHandler.java:16) [TickHandler.class:?]
    at cpw.mods.fml.common.eventhandler.ASMEventHandler_886_TickHandler_foo_ServerTickEvent.invoke(.dynamic) [?:?]
    at cpw.mods.fml.common.eventhandler.ASMEventHandler.invoke(ASMEventHandler.java:54) [ASMEventHandler.class:?]
    at cpw.mods.fml.common.eventhandler.EventBus.post(EventBus.java:140) [EventBus.class:?]
    at cpw.mods.fml.common.FMLCommonHandler.onPostServerTick(FMLCommonHandler.java:247) [FMLCommonHandler.class:?]
    at net.minecraft.server.MinecraftServer.func_71217_p(MinecraftServer.java:590) [MinecraftServer.class:?]
    at net.minecraft.server.integrated.IntegratedServer.func_71217_p(IntegratedServer.java:111) [bsx.class:?]
    at fastcraft.ag.a(F:981) [fastcraft-1.22-ctest18.jar:?]
    at fastcraft.H.aq(F:21) [fastcraft-1.22-ctest18.jar:?]
    at net.minecraft.server.MinecraftServer.run(MinecraftServer.java:396) [MinecraftServer.class:?]
    at net.minecraft.server.MinecraftServer$2.run(MinecraftServer.java:685) [?:?]
Caused by: java.lang.IllegalStateException: Entity is already tracked!
    at net.minecraft.entity.EntityTracker.func_72785_a(EntityTracker.java:196) ~[mn.class:?]
    at cpw.mods.fml.common.registry.EntityRegistry.tryTrackingEntity(EntityRegistry.java:364) ~[EntityRegistry.class:?]
    at net.minecraft.entity.EntityTracker.func_72786_a(EntityTracker.java:61) ~[mn.class:?]
    at net.minecraft.world.WorldManager.func_72703_a(SourceFile:31) ~[mp.class:?]
    at net.minecraft.world.World.func_72923_a(World.java:1347) ~[ahb.class:?]
    at net.minecraft.world.WorldServer.func_72923_a(WorldServer.java:844) ~[mt.class:?]
    at net.minecraft.world.World.func_72868_a(World.java:3304) ~[ahb.class:?]
    at net.minecraft.world.chunk.Chunk.func_76631_c(Chunk.java:921) ~[apx.class:?]
    at net.minecraftforge.common.chunkio.ChunkIOProvider.callStage2(ChunkIOProvider.java:46) ~[ChunkIOProvider.class:?]
    at net.minecraftforge.common.chunkio.ChunkIOProvider.callStage2(ChunkIOProvider.java:12) ~[ChunkIOProvider.class:?]
    at net.minecraftforge.common.util.AsynchronousExecutor.skipQueue(AsynchronousExecutor.java:344) ~[AsynchronousExecutor.class:?]
    at net.minecraftforge.common.util.AsynchronousExecutor.getSkipQueue(AsynchronousExecutor.java:302) ~[AsynchronousExecutor.class:?]
    at net.minecraftforge.common.chunkio.ChunkIOExecutor.syncChunkLoad(ChunkIOExecutor.java:12) ~[ChunkIOExecutor.class:?]
    at net.minecraft.world.gen.ChunkProviderServer.loadChunk(ChunkProviderServer.java:126) ~[ms.class:?]
    at net.minecraft.world.gen.ChunkProviderServer.func_73158_c(ChunkProviderServer.java:101) ~[ms.class:?]
    at net.minecraft.world.gen.ChunkProviderServer.func_73154_d(ChunkProviderServer.java:199) ~[ms.class:?]
    at net.minecraft.world.World.func_72964_e(World.java:419) ~[ahb.class:?]
    at com.draco18s.ores.util.OreDataHooks.saveData(OreDataHooks.java:176) ~[OreDataHooks.class:?]
    at com.draco18s.ores.OresEventHandler.chunkSave(OresEventHandler.java:314) ~[OresEventHandler.class:?]
    at cpw.mods.fml.common.eventhandler.ASMEventHandler_1610_OresEventHandler_chunkSave_Save.invoke(.dynamic) ~[?:?]
    at cpw.mods.fml.common.eventhandler.ASMEventHandler.invoke(ASMEventHandler.java:54) ~[ASMEventHandler.class:?]
    at cpw.mods.fml.common.eventhandler.EventBus.post(EventBus.java:140) ~[EventBus.class:?]
    at net.minecraft.world.chunk.storage.AnvilChunkLoader.func_75816_a(AnvilChunkLoader.java:198) ~[aqk.class:?]
    at net.minecraft.world.gen.ChunkProviderServer.func_73242_b(ChunkProviderServer.java:256) ~[ms.class:?]
    at sun.reflect.GeneratedMethodAccessor40.invoke(Unknown Source) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_74]
    at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_74]
    at mcp.mobius.pregen.exec.PregenExec.exec(PregenExec.java:188) ~[PregenExec.class:?]
    at mcp.mobius.pregen.TickHandler.foo(TickHandler.java:16) ~[TickHandler.class:?]
    at cpw.mods.fml.common.eventhandler.ASMEventHandler_886_TickHandler_foo_ServerTickEvent.invoke(.dynamic) ~[?:?]
    at cpw.mods.fml.common.eventhandler.ASMEventHandler.invoke(ASMEventHandler.java:54) ~[ASMEventHandler.class:?]
    at cpw.mods.fml.common.eventhandler.EventBus.post(EventBus.java:140) ~[EventBus.class:?]
    at cpw.mods.fml.common.FMLCommonHandler.onPostServerTick(FMLCommonHandler.java:247) ~[FMLCommonHandler.class:?]
    at net.minecraft.server.MinecraftServer.func_71217_p(MinecraftServer.java:590) ~[MinecraftServer.class:?]
    at net.minecraft.server.integrated.IntegratedServer.func_71217_p(IntegratedServer.java:111) ~[bsx.class:?]
    ... 2 more
[14:32:08] [Client thread/INFO]: [CHAT] Generated 200 / 40000 chunks [ 0.50% ]

This probably doesn't belong anymore on @lawremi's issue tracker. :)

[Draco18s]

Oh geeze.

Well, feel free to figure out what I can do better.

https://gist.github.com/Draco18s/6b6a622dfac669b399ec

[Haggle1996]

I don't think this is you. I reran with the minimal mod set and the error never appeared. Looking at the code, it's probably some mod interaction that happens to fire when you're checking the chunk.

Still have the memory issues with flower generation -- what if anything can I do to help track that down?

[Draco18s]

I am not sure. I'm also pretty busy on another project, so I can't devote a lot of time to this, either.

[LemADEC]

@Draco18s getChunkFromChunkCoords will actually load the chunk, which is what you want to avoid in the first place. The isChunkLoaded is misnamed on that matter. Instead, you can try something like this: https://github.com/LemADEC/WarpDrive/blob/MC1.7/src/main/java/cr0s/warpdrive/data/VectorI.java#L110

[Draco18s]

Interesting. Thanks for the heads up.

[Draco18s]

Another problem that cropped up that was much easier to solve, combined with a weekend that I decided to work on a small side project (which collapsed in a flaming ruin last night) meant I got around to finally fixing this. Hopefully it works better!

Look for 14.22.0 later today.

[Haggle1996]

Awesome, thank you! I'll let you know how it goes.

[Draco18s]

Keybounce is doing a memory comparison for me right now. We'd previously done "are chunks staying loaded according to map mod" testing and that hadn't been showing problems previously, so hopefully the "load a bunch of chunks and count RAM" shows an improvement.

[Draco18s]

RC build, let me know if you notice a problem in the next couple hours. https://dl.dropboxusercontent.com/u/7950499/1.7.10-ReasonableRealism-13.24.0aaaaa.jar

[Haggle1996]

checking it out now.

[Haggle1996]

Sadly, not able to run it. Receive this error on creating a new world: https://gist.github.com/Haggle1996/c065e33bf96362df8c9c85e5182f8c77

[Draco18s]

o..O That's...really weird. That's the same file I gave to Keybounce. Client or dedicated server? (Shouldn't matter, that build literally changed two things to fix two issues, neither of them should have done that).

[Haggle1996]

I'm able to reload the world and keep going, but so far 2/2 crashing on new worlds. SSP. I should delete my configs and let them regenerate. I may have derped something.

World gen is significantly faster, so far.

[Draco18s]

Just finished creating a new world myself on an existing instance (RR, IC2, Gany's Surface, NEI, WAILA). I don't have nearly the collection of mods that you're running with though (and tracking them all down is a right pain, as I would never use most of them).

[Haggle1996]

You can always get my pack on the atlauncher, but no worries. I had just dropped it into my latest version and deleted the old Harder stuff.

Is it possible to provide me a test version without harder underground? I don't use this one.

[Haggle1996]

Or is it safe to delete the hazards folder out of the jar?

[Draco18s]

Sure, no problem. Here's a zip of the full set of separated jar files. https://dl.dropboxusercontent.com/u/7950499/RR-all.rar

(Also, yes, it would be safe to delete Hazards from the jar; it's just an automated packaging like the zip linked in this post).

[Draco18s]

Keybounce is still reporting a memory leak somewhere but we aren't sure where/why.

[Haggle1996]

Yar, I'm still leaking memory. World gen is much faster, though.

[Draco18s]

Headscratches Take Wildlife out for a moment and see if the problem goes away, located another spot where I was doing "bad" isChunkLoaded, thought it should have had minimal impact.

[Haggle1996]

Testing now.

[Haggle1996]

Regenerating my configs, btw, seems to have fixed the ticking memory crash. Sorry for the crash report.

[Draco18s]

No worries, it seems to happen (to mods in general) and the error is buried inside Forge's networking code.

[Haggle1996]

No change in memory performance without harder wildlife.

[Draco18s]

Ok...so what am I missing?

Up uploading the full source to my github repo, feel free to dig into anything that looks like it might be the culprit.

[Draco18s]

I found one of two issues leading to the observed behavior. Issue I found and fixed: Somehow oredata was being stored for areas in the sky above the build height. Up as high as 4000 blocks. Fixed that. Memory usage for the storage should drop from hundreds of thousands of entries to single digit thousands. Issue I still don't understand: data not being properly removed from the map when a chunk unloads. I even wrote a method to do periodic full-scan to validate every location still being tracked...with disastrous results: [1:52:38 AM] Tracked data size was: 4963, now: 0, down: 4963 Why? WHY?

;_;

Making the fixes I can, hopefully it will keep the issue at bay enough for it to not be a problem.

Updated the zip https://dl.dropboxusercontent.com/u/7950499/RR-all.rar

[Haggle1996]

Sorry; sleep comes first. :) Testing now.

[Haggle1996]

BTW, the rar has two versions of each file... .13 and .14, I assume the higher is supposed to be tested?

[Haggle1996]

I'd have to say the last version, .14, is a complete success!

I was able to pregenerate a 40,000 chunk area (200x200 chunks) in one sitting without ever going out of memory. Started at 2.8GB, ended 4.1GB, versus starting at 2.8 and climbing to 16GB and exploding, and the generation process getting slower and slower. Quite awesome!

[Draco18s]

Er, yeah, I was just shoving new jars into the same zip (I forgot I changed the #s). Anyway, glad its under control now.

(Sleep? Sleep is for the weak)

[Haggle1996]

I'm going to close this issue. The update is AMAZING. The number 1 problem that kills players from even trying my pack has been the world gen issues. THANK YOU THANK YOU THANK YOU!

And thank you to lawremi too...sorry we clouded up your tracker.