Closed Speiger closed 3 years ago
Won-Ton
commented
3 years ago Also next time: please don't be an ass and lock everything the moment someone report an issue. Referencing #140
Hi. Sorry. chill. I have a macro that locked it & as you can see I unlocked it again when I realised...
Will take a look at the dump when I have time, that's a bit more useful. What spec is your machine btw? (in particular core/thread count)
Won-Ton
commented
3 years ago Logs might also be useful. One of the task-worker threads is waiting on a batch of work to be completed, but all four of the batch-worker threads are waiting for work from their executor. Were any exceptions thrown? Looks like some sort of error or race condition has occurred between setting up the batcher and feeding it with work.
Speiger
commented
3 years ago Hi. Sorry. chill. I have a macro that locked it & as you can see I unlocked it again when I realised...
Yeah, you effectively were the guy who says: "I don't care" Shuts door into the face. I personally would kill that macro, but its fine, just terrible first impression.
About your request about the logs. Outside of my pregenerator spam that lands in chat when you run a pregeneration, there is not much useful left.
The only thing i have is this:
[03Aug2021 02:35:53.697] [Server thread/INFO] [net.minecraft.server.MinecraftServer/]:
[Task Name: Preview_minecraft:dimension]
[World: Overworld] [Task Type: FAST_CHECK_GEN]
[Task (Main : Light/Total) (4,128 : 1,044) / 40,000]
[Speed (Main | Light): 1.31 Chunks/t | 0.37 Chunks/t]
[Loaded (Chunks | RegionFiles | POI): 7654 | 21 | 1904]
[Time Left (Main | Light), Running: 00:22:45 | 01:27:40, 00:02:37]
[Ram Usage: 2240MB]
[03Aug2021 02:35:54.502] [Thread-2/DEBUG] [net.minecraftforge.fml.config.ConfigFileTypeHandler/CONFIG]: Config file PregenConfig.toml changed, sending notifies
[03Aug2021 02:35:54.510] [Thread-2/DEBUG] [net.minecraftforge.fml.config.ConfigFileTypeHandler/CONFIG]: Config file PregenConfig.toml changed, sending notifies
[03Aug2021 02:36:06.499] [pool-7-thread-1/INFO] [Chunk Pregenerator/]: Removing Server: true
[03Aug2021 02:36:06.548] [Server thread/INFO] [net.minecraft.server.MinecraftServer/]: Stopping server
[03Aug2021 02:36:06.548] [Server thread/INFO] [net.minecraft.server.MinecraftServer/]: Saving players
[03Aug2021 02:36:06.548] [Server thread/INFO] [net.minecraft.server.MinecraftServer/]: Saving worlds
[03Aug2021 02:36:06.548] [Server thread/INFO] [net.minecraft.server.MinecraftServer/]: Saving chunks for level 'ServerLevel[New World]'/minecraft:overworld
[03Aug2021 02:36:07.842] [Server thread/INFO] [net.minecraft.world.server.ChunkManager/]: ThreadedAnvilChunkStorage (Preview): All chunks are saved
[03Aug2021 02:36:07.842] [Server thread/INFO] [net.minecraft.server.MinecraftServer/]: Saving chunks for level 'ServerLevel[New World]'/minecraft:the_nether
[03Aug2021 02:36:07.845] [Server thread/INFO] [net.minecraft.world.server.ChunkManager/]: ThreadedAnvilChunkStorage (DIM-1): All chunks are saved
[03Aug2021 02:36:07.845] [Server thread/INFO] [net.minecraft.server.MinecraftServer/]: Saving chunks for level 'ServerLevel[New World]'/minecraft:the_end
[03Aug2021 02:36:07.848] [Server thread/INFO] [net.minecraft.world.server.ChunkManager/]: ThreadedAnvilChunkStorage (DIM1): All chunks are saved
[03Aug2021 02:36:07.861] [Server thread/DEBUG] [net.minecraftforge.fml.FMLWorldPersistenceHook/WP]: Gathering id map for writing to world save New World
[03Aug2021 02:36:07.870] [Server thread/DEBUG] [net.minecraftforge.fml.FMLWorldPersistenceHook/WP]: ID Map collection complete New World
[03Aug2021 02:36:07.912] [Server thread/INFO] [net.minecraft.world.server.ChunkManager/]: ThreadedAnvilChunkStorage (Preview): All chunks are saved
[03Aug2021 02:36:08.678] [Server thread/INFO] [net.minecraft.world.server.ChunkManager/]: ThreadedAnvilChunkStorage (DIM-1): All chunks are saved
[03Aug2021 02:36:08.679] [Server thread/INFO] [net.minecraft.world.server.ChunkManager/]: ThreadedAnvilChunkStorage (DIM1): All chunks are saved
[03Aug2021 02:36:09.072] [Server thread/DEBUG] [net.minecraftforge.fml.loading.FileUtils/CORE]: Found existing serverconfig directory : E:\Games\MC\MultiMC\instances\1.16.52\.minecraft\saves\Preview\serverconfig
[03Aug2021 02:36:09.072] [Server thread/DEBUG] [net.minecraftforge.fml.config.ConfigTracker/CONFIG]: Unloading configs type SERVER
[03Aug2021 02:36:11.735] [Render thread/INFO] [net.minecraft.client.Minecraft/]: Stopping!
[03Aug2021 02:36:14.784] [TF-Task-Worker-1/INFO] [STDERR/]: [com.terraforged.engine.concurrent.batch.TaskBatcher:close:94]: java.lang.InterruptedException
[03Aug2021 02:36:14.785] [TF-Task-Worker-1/INFO] [STDERR/]: [com.terraforged.engine.concurrent.batch.TaskBatcher:close:94]: at java.lang.Object.wait(Native Method)
[03Aug2021 02:36:14.785] [TF-Task-Worker-1/INFO] [STDERR/]: [com.terraforged.engine.concurrent.batch.TaskBatcher:close:94]: at java.lang.Object.wait(Unknown Source)
[03Aug2021 02:36:14.785] [TF-Task-Worker-1/INFO] [STDERR/]: [com.terraforged.engine.concurrent.batch.TaskBatcher:close:94]: at com.terraforged.engine.concurrent.batch.TaskBatcher.close(TaskBatcher.java:92)
[03Aug2021 02:36:14.785] [TF-Task-Worker-1/INFO] [STDERR/]: [com.terraforged.engine.concurrent.batch.TaskBatcher:close:94]: at com.terraforged.engine.tile.gen.TileGeneratorBatched.generateRegion(TileGeneratorBatched.java:42)
[03Aug2021 02:36:14.785] [TF-Task-Worker-1/INFO] [STDERR/]: [com.terraforged.engine.concurrent.batch.TaskBatcher:close:94]: at com.terraforged.engine.tile.gen.CallableTile.create(CallableTile.java:44)
[03Aug2021 02:36:14.785] [TF-Task-Worker-1/INFO] [STDERR/]: [com.terraforged.engine.concurrent.batch.TaskBatcher:close:94]: at com.terraforged.engine.tile.gen.CallableTile.create(CallableTile.java:30)
[03Aug2021 02:36:14.785] [TF-Task-Worker-1/INFO] [STDERR/]: [com.terraforged.engine.concurrent.batch.TaskBatcher:close:94]: at com.terraforged.engine.concurrent.task.LazyCallable.call(LazyCallable.java:68)
[03Aug2021 02:36:14.785] [TF-Task-Worker-1/INFO] [STDERR/]: [com.terraforged.engine.concurrent.batch.TaskBatcher:close:94]: at java.util.concurrent.FutureTask.run(Unknown Source)
[03Aug2021 02:36:14.786] [TF-Task-Worker-1/INFO] [STDERR/]: [com.terraforged.engine.concurrent.batch.TaskBatcher:close:94]: at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
[03Aug2021 02:36:14.786] [TF-Task-Worker-1/INFO] [STDERR/]: [com.terraforged.engine.concurrent.batch.TaskBatcher:close:94]: at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
[03Aug2021 02:36:14.786] [TF-Task-Worker-1/INFO] [STDERR/]: [com.terraforged.engine.concurrent.batch.TaskBatcher:close:94]: at java.lang.Thread.run(Unknown Source)
[03Aug2021 02:36:14.786] [Worker-Main-12/ERROR] [net.minecraft.util.concurrent.DelegatedTaskExecutor/]: Cound not schedule mailbox
java.util.concurrent.RejectedExecutionException: null
at java.util.concurrent.ForkJoinPool.externalSubmit(Unknown Source) ~[?:1.8.0_161]
at java.util.concurrent.ForkJoinPool.externalPush(Unknown Source) ~[?:1.8.0_161]
at java.util.concurrent.ForkJoinPool.execute(Unknown Source) ~[?:1.8.0_161]
at net.minecraft.util.concurrent.DelegatedTaskExecutor.func_213143_f(SourceFile:126) ~[?:?]
at net.minecraft.util.concurrent.DelegatedTaskExecutor.func_212871_a_(SourceFile:115) ~[?:?]
at net.minecraft.world.chunk.ChunkTaskPriorityQueueSorter.func_219078_a(SourceFile:142) ~[?:?]
at net.minecraft.world.chunk.ChunkTaskPriorityQueueSorter.func_219088_a(SourceFile:150) ~[?:?]
at java.util.concurrent.CompletableFuture.uniAccept(Unknown Source) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture$UniAccept.tryFire(Unknown Source) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.postComplete(Unknown Source) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.complete(Unknown Source) ~[?:1.8.0_161]
at net.minecraft.util.concurrent.ITaskExecutor$1.func_212871_a_(SourceFile:44) ~[?:?]
at net.minecraft.world.chunk.ChunkTaskPriorityQueueSorter.func_219083_b(SourceFile:59) ~[?:?]
at net.minecraft.util.concurrent.DelegatedTaskExecutor.func_213148_e(SourceFile:94) [?:?]
at net.minecraft.util.concurrent.DelegatedTaskExecutor.func_213145_a(SourceFile:137) [?:?]
at net.minecraft.util.concurrent.DelegatedTaskExecutor.run(SourceFile:105) [?:?]
at java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(Unknown Source) [?:1.8.0_161]
at java.util.concurrent.ForkJoinTask.doExec(Unknown Source) [?:1.8.0_161]
at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(Unknown Source) [?:1.8.0_161]
at java.util.concurrent.ForkJoinPool.runWorker(Unknown Source) [?:1.8.0_161]
at java.util.concurrent.ForkJoinWorkerThread.run(Unknown Source) [?:1.8.0_161]This crashlog is directly after i manually killed the world and interrupted my pregeneration. (Also the first image shows that the server thread was dead but thread workers were still running.)
This was out of the debug log so everything that was logged was in there.
If you want to try it yourself here is the file that i used for pregeneration test. (Curseforge is down thats why a direct file and not a Link). ChunkPregenerator.zip
There is 3 ways you can make a test: 1: Preview
2: Ingame command Gui.
3: Command
All 3 do the exact same thing the only difference is that first way is starting a custom integrated server that just disables the Automatic Player Joining, otherwise its exactly the same.
Won-Ton
commented
3 years ago you effectively were the guy who says: "I don't care" Shuts door into the face. I personally would kill that macro, but its fine, just terrible first impression.
Most people use the text messages to communicate on github. I wouldn't read too much into what actions people take to manage their issue tracker; you'll have a calmer and more pleasant experience for it :]
Thanks for the extra info. I will sink some time into investigating it.
Speiger
commented
3 years ago What spec is your machine btw? (in particular core/thread count)
I missed that one. 4 Cores 4 Threads, Unless its a single core it should not matter. Dual Cores should be supported at the very minimum. (Most servers are dual cores that are offered and what MC actually expects at minimum)
Thanks for the extra info. I will sink some time into investigating it.
Good Luck, if you need any help tell me i will try to assist as good as possible
Won-Ton
commented
3 years ago The min spec is 4 thread cpus. Obviously that'll be for clients but it's a pretty reasonable spec for modded mc and it's what we aim to support with TF (we usually tell people to pregen on low-resource hardware such as shared hosting).
So far with testing... no luck. Generated about 500k chunks over a few different seeds without success (aka failure [aka deadlock!]). Tested one pregen so far with cores limited to 4 but it completed without issue.
My profiling did show some of the chunk-gen threads (Worker-Main) were waiting on the batcher lock. I don't think that should be an issue but it's easy enough to change so that only the TF-Task threads wait there. Just means the Worker-Main's would be waiting on a Future#get instead.
The only time the Server thread was blocked was when it and one of the Worker-Main threads were accessing a synchronized Long2ObjectMap in the light engine. This occurred only once and was not detrimental since the pregen finished.
I'll try a few tweaks to TF's batcher and maybe throw up a jar here for testing if that's cool (since I can't reproduce a deadlock so far I can't really test if the changes help or not).
Speiger
commented
3 years ago That is interesting, that you didn't get any hits. I did it first try. Maybe it is a race condition that is more likely to be hit on weaker hardware. though i doubt that you would count a i5-7500 a weak CPU.
Maybe throw in some timeouts and some logs so i can provide you with logs of what is happening? Like a quick custom version i can test tomorrow?
Also side question, do you account for that mc is also able to generate in multiple dimensions at the same time? (So if you had 7 cores (with vanilla) you could generate 7 dimensions at the same time)
Won-Ton
commented
3 years ago Will try get something up promptly.
Re side Q: There's not much for us to account for unless I'm missing the point? TF doesn't use vanilla's threadpools (as-in submit new tasks to them) so how those are saturated & managed is entirely up to vanilla. We just have to try do our execution quickly when our chunkgenerator is called on those work threads to keep things ticking. If our execution doesn't complete for any reason then that is a problem regardless of how many chunks/dimensions are currently generating, as that hang eventually propagates back to the game thread
Speiger
commented
3 years ago Re side Q:
Ok good to know. Worry was more like what if the vanilla threadpool fills up. (Especially since vanilla chunkrequests for gameplay go through that threadpool too if the chunks are not loaded)
Will try get something up promptly.
Ok i am already testing the port for the new cp version too.
Won-Ton
commented
3 years ago This incorporates a couple of the tweaks to TF's batcher and cache.
It also puts a 10 second timeout on the on the batcher's await for debugging purposes.
Won-Ton
commented
3 years ago also @NillerMedDild ^
Speiger
commented
3 years ago Ok starting up testspace
Edit: Outside of the CPU i have the same GPU & double of his ram. (8GB for mc)
Speiger
commented
3 years ago Ok first feedback this new version is not getting stuck "Yet". Already 34k chunks in. I am going to do a 250k chunk test afterwards to see if it gets stuck.
Also thread pool no longer gets stuck either. At all.
Speiger
commented
3 years ago Ok 40k chunks is done the 250k chunks is now started. This will most likely takes 1 hour to finish. if that is not failing for me (and maybe @NillerMedDid) if you don't have any issues then i would say its fixed.
The only worry i have is that Terraforged has a memory leak. (40k chunks added 500MB of Unclearable Ramusage) which is a bit much for a world that only had spawn chunks loaded. Could be only a hunch but i am awaiting the Large scale test to validate it I will create a memory dump if the hunch turns out correct and give it to you.
Basically any data that is stored as "WorldSavedData" and is chunk based is viewed as memory leak since it should be stored in a chunk just to give examples if you know some things that would fall under that category
NielsPilgaard
commented
3 years ago 2 out of 2 new worlds loaded successfully, looking good so far 👍
Won-Ton
commented
3 years ago re: possible memory leak
It's probably com.terraforged.engine.cell.Cell (and arrays of them). Cells make up the data generated for TF's heightmap. The heightmap is generated in multi-chunk tiles of these cells so they are cached externally of chunks. The cache is fixed size and cleaned periodically. We also expell tiles once all chunks in them have been visited. The cell instances and arrays are pooled (again, fixed size so anything in excess is released for GC).
Won-Ton
commented
3 years ago Sounds promising, anyway. I'm testing a theory as to what might have been happening
Speiger
commented
3 years ago If memory is stable after 200k chunks i call this not a memory leak. Its just something that is on my "ALARM" list when i check mods with CP so we can fix all bugs and make sure its compatible with generating 2.5Billion Chunks.
NielsPilgaard
commented
3 years ago I got stuck on 100% on the 3rd try latest.log stuck-loading-singleplayer-testjar.zip
Speiger
commented
3 years ago @NillerMedDild include the debug.log too. It includes everything not just "info/warn/error".
NielsPilgaard
commented
3 years ago I had debug log generation disabled, will enable it for tests 5 and up :)
Won-Ton
commented
3 years ago I'm thinking that might be unrelated. Looks like it made it to 100% gen'd because it goes on to fire the server started event
Speiger
commented
3 years ago @NillerMedDild if it happens again get the seed because maybe it is seedbased.
NielsPilgaard
commented
3 years ago The seed was 7440752932931600011
Speiger
commented
3 years ago @Won-Ton ok Memory leak is not correct. After 250k chunks it uses 1.2GB of ram after a forced GC (i have a command with Pregen) So all within a perfect range. Now going to try the seed Niller Provided
Speiger
commented
3 years ago Seed does not get stuck this is most likely one of the Forge Proxy Packet bugs. (Basically if the world lags to much it cancels the join. Even in singleplayer. Forges Fix: Get a better PC) Gregtech 6 had this issue a lot in 1.7.10 and this is still a issue, we got it down to a science.
Speiger
commented
3 years ago Last test. I am going to test it with the new patch for pregen and look if that is having a issue (a quick 40k gen) if not i call it fixed on my side.
NielsPilgaard
commented
3 years ago 6 / 7 new TF worlds have now loaded successfully, I'm gonna continue to 10.
Speiger
commented
3 years ago Yeah works fine. New logic is roughly 20% faster with terrain gen. Though Light engine is now less stressed out. But all with in acceptable ranges.
So from my side you are fine. I am going to release my new version the coming weekend. Whats your ETA @Won-Ton with Terraforged? (So i can provide a Service message)
NielsPilgaard
commented
3 years ago The results are in, and 9 / 10 new TF worlds started successfully with the patched version. Thanks for the fix!
Won-Ton
commented
3 years ago Cool I'll have a release pushed within the next 48hrs
Speiger
commented
3 years ago Added a service message for within this week. More fair for you if stuff fucks up.
Only mods being used ChunkPregenerator and the other is Terraforged latest curse version.
What i did was: Create new World set it to Terraforged type and started a preview/normal worldgeneration. After roughly 2k chunks it just stops generating. (which is when the TF-Task-Worker-2 is basically finished.
Thread Profiler to show what happened:
And also looking over the other threads. It looks like Terraforged Blocks the Worldgen thread too.
Also include the Thread Dump. threadDump.zip
Also next time: please don't be an ass and lock everything the moment someone report an issue. Referencing #140
To give some guesses: I think you are "offthreading" something that is already offthread. To a point where you can have loops that can deadlock. As you can see that actually happened.