[1.7.2][Unsolved] massive lags checkedPosition < toCheckCount

[TeNNoX]

I have a mod with custom World Generation (Planetoids), but it has some problems with massive lags. The Minecraft profiler identifies the section "root.tick.level.chunkCache.recheckGaps.checkedPosition < toCheckCount" as the problem.

(The section is located in World.updateLightByType(...))

 

Do you know by what this is caused (I know it's lighting) and maybe even how to fix this?

[TheGreyGhost]

Hi

 

Looks to me like your mod is changing something frequently that triggers Minecraft to recalculate the sky light and block light for each block over and over.  That is expensive (hence the reason that vanilla saves those values and only recalculates them when necessary).

 

Some examples are - changing the opacity of a type of block; changing the amount of light produced by "glowing" blocks.  Each change in one of those triggers a cascading recalculation of all the blocks nearby, which takes a very long time.

 

If you're doing anything like that, try commenting it out and see if the lag disappears.

 

I presume the lag is during game, not during world generation?

 

-TGG

 

PS

Some bg info on lighting here...

 

http://greyminecraftcoder.blogspot.com.au/2013/08/lighting.html

 

 

[TeNNoX]

Looks to me like your mod is changing something frequently that triggers Minecraft to recalculate the sky light and block light for each block over and over.  That is expensive (hence the reason that vanilla saves those values and only recalculates them when necessary).

 

Some examples are - changing the opacity of a type of block; changing the amount of light produced by "glowing" blocks.  Each change in one of those triggers a cascading recalculation of all the blocks nearby, which takes a very long time.

 

If you're doing anything like that, try commenting it out and see if the lag disappears.

 

I presume the lag is during game, not during world generation?

 

-TGG

 

Well, the mod only provides World Generation, it is not changing anything after finished generating a chunk.

There are no custom blocks or anything like that and I don't change any opacity or light values

 

I only experience the lags ingame, but the world generation takes abnormally long. (I can't see the profiler in the loading world screen)

I keep getting these messages in the log:

[14:14:25] [Client thread/WARN]: Something's taking too long! 'root.tick.level.chunkCache' took aprox 286.612826 ms
[14:14:25] [Client thread/WARN]: Something's taking too long! 'root.tick.level' took aprox 302.049894 ms
[14:14:25] [Client thread/WARN]: Something's taking too long! 'root.tick' took aprox 309.558255 ms
[14:14:25] [Client thread/WARN]: Something's taking too long! 'root' took aprox 339.65235 ms
[14:14:26] [Client thread/WARN]: Something's taking too long! 'root.tick.gameMode' took aprox 269.158475 ms
[14:14:26] [Client thread/WARN]: Something's taking too long! 'root.tick' took aprox 272.695252 ms
[14:14:26] [Client thread/WARN]: Something's taking too long! 'root' took aprox 299.881455 ms

(both contain the section "checkedPosition < toCheckCount")

 

Do you know how to make profile dumps (LIKE THIS ONE), with something like this I could find out if the abnormally world generation is caused by the same thing. It is not caused by my own world generation code, I added some time-measuring functions to all methods, and they add up to 3-4 seconds, the world generation takes 10+

[TheGreyGhost]

Hi

 

You get the profile dumps by issuing the command

/debug start

 

debug <(start | stop)> Starts a new debug profiling session or stops the session currently running. It notifies about potential performance bottlenecks in the console when active and creates a profiler results file in the folder debug when stopped.

 

-TGG

[TeNNoX]

You get the profile dumps by issuing the command

/debug start

 

debug <(start | stop)> Starts a new debug profiling session or stops the session currently running. It notifies about potential performance bottlenecks in the console when active and creates a profiler results file in the folder debug when stopped.

 

-TGG

 

So I can't test that while generating...

 

Here is a profiling session dump: (ingame)

http://pastebin.com/RaY481Rt

 

Do you have an idea what could cause the lag? As I said:

the mod only provides World Generation, it is not changing anything after finished generating a chunk.

There are no custom blocks or anything like that and I don't change any opacity or light values

 

A guy also informed me that the lag is appearing mostly on serverside when running client/server seperately. (mostly world generation again)

 

[TheGreyGhost]

hi

 

Sorry dude, nothing leaps out at me.  It sure is spending a lot of time doing lighting updates, but that's not unusual and vanilla normally "paces itself" to stop it causing game slowdown.

And recheckGaps  checkedPosition < toCheckCount doesn't actually seem to be taking much time at all.

 

Those error messages

[14:14:25] [Client thread/WARN]: Something's taking too long! 'root.tick.level.chunkCache' took aprox 286.612826 ms

are a bit of a mystery to me too.

 

It looks to me like the chunkCache for client side only calls

        this.clientChunkProvider.unloadQueuedChunks();

which should return false immediately, so I don't understand what's happening there.  Unless you have accidentally replaced it with something that takes a lot of time?  Could perhaps be related to garbage collection, if your world generation is creating and abandoning a large number of objects.

 

In the absence of any better ideas, you could perhaps try removing parts of your code until the problem goes away - process of elimination.

 

Unfortunately I'm stumped, sorry!

 

-TGG

[TeNNoX]

hi

 

Sorry dude, nothing leaps out at me.  It sure is spending a lot of time doing lighting updates, but that's not unusual and vanilla normally "paces itself" to stop it causing game slowdown.

And recheckGaps  checkedPosition < toCheckCount doesn't actually seem to be taking much time at all.

 

Those error messages

[14:14:25] [Client thread/WARN]: Something's taking too long! 'root.tick.level.chunkCache' took aprox 286.612826 ms

are a bit of a mystery to me too.

 

It looks to me like the chunkCache for client side only calls

        this.clientChunkProvider.unloadQueuedChunks();

which should return false immediately, so I don't understand what's happening there.  Unless you have accidentally replaced it with something that takes a lot of time?  Could perhaps be related to garbage collection, if your world generation is creating and abandoning a large number of objects.

 

In the absence of any better ideas, you could perhaps try removing parts of your code until the problem goes away - process of elimination.

 

Unfortunately I'm stumped, sorry!

 

-TGG

 

the main problem still seems to be: (=> checkedPosition < toCheckCount)

[Client thread/WARN]: Something's taking too long! 'root.tick.level.chunkCache.recheckGaps' took aprox 1349.424627 ms

 

I tried deleting all stuff in PlanetoidChunkProvider and rewriting it after a tutorial. It works fine, but I got a default world. Then I removed the default generation code -> still works fine. (World generation takes about 5-10 seconds)

When I added the planet generation code though, the problems came up again. The weird thing is: the provideChunk method (generation of the planets) is only taking up 3-5 seconds in the whole generation process, which takes 40-50 seconds!!

 

 

When I disabled all planetoids except DIRT, I got this profile dump:

 

--- BEGIN PROFILE DUMP ---
[00] connection - 51,63%/51,63%
[01]  checkedPosition < toCheckCount - 59,05%/30,48%
[01]  unspecified - 26,32%/13,59%
[01]  getBrightness - 13,66%/7,05%
[01]  checkLight - 0,89%/0,46%
[02]   checkedPosition < toCheckCount - 81,58%/0,38%
[02]   unspecified - 11,14%/0,05%
[02]   getBrightness - 7,28%/0,03%
[01]  travel - 0,03%/0,02%
[02]   unspecified - 55,11%/0,01%
[02]   move - 23,65%/0,00%
[02]   rest - 21,23%/0,00%
[01]  entityBaseTick - 0,01%/0,01%
[02]   unspecified - 87,13%/0,00%
[02]   portal - 12,87%/0,00%
[01]  livingEntityBaseTick - 0,01%/0,00%
[01]  ai - 0,01%/0,00%
[02]   unspecified - 50,24%/0,00%
[02]   oldAi - 49,76%/0,00%
[01]  move - 0,01%/0,00%
[01]  rest - 0,01%/0,00%
[01]  headTurn - 0,00%/0,00%
[01]  keepAlive - 0,00%/0,00%
[01]  push - 0,00%/0,00%
[01]  rangeChecks - 0,00%/0,00%
[01]  playerTick - 0,00%/0,00%
[01]  jump - 0,00%/0,00%
[00] levels - 48,10%/48,10%
[01]  Copy of Planetoid start - 99,90%/48,05%
[02]   tick - 99,51%/47,82%
[03]    tickBlocks - 89,20%/42,66%
[04]     tickChunk - 96,90%/41,33%
[05]      unspecified - 47,11%/19,47%
[05]      getBrightness - 29,54%/12,21%
[05]      recheckGaps - 16,94%/7,00%
[06]       unspecified - 39,51%/2,77%
[06]       checkedPosition < toCheckCount - 33,70%/2,36%
[06]       getBrightness - 26,79%/1,88%
[05]      checkedPosition < toCheckCount - 6,41%/2,65%
[04]     tickBlocks - 1,79%/0,77%
[05]      unspecified - 99,84%/0,76%
[05]      checkLight - 0,16%/0,00%
[06]       checkedPosition < toCheckCount - 76,37%/0,00%
[06]       unspecified - 18,79%/0,00%
[06]       getBrightness - 4,84%/0,00%
[04]     unspecified - 0,98%/0,42%
[04]     iceandsnow - 0,13%/0,05%
[04]     getChunk - 0,07%/0,03%
[04]     buildList - 0,05%/0,02%
[04]     thunder - 0,03%/0,01%
[04]     playerCheckLight - 0,02%/0,01%
[05]      unspecified - 54,25%/0,00%
[05]      getBrightness - 43,17%/0,00%
[05]      checkedPosition < toCheckCount - 2,58%/0,00%
[04]     checkLight - 0,02%/0,01%
[04]     moodSound - 0,01%/0,01%

 

 

In the console the profiler is mostly complaining about:

Something's taking too long! 'root.levels.WORLDNAME.tick.tickBlocks.tickChunk' took aprox 112.277802 ms

and as you can see the topmost timeconsuming thing is

checkedPosition < toCheckCount - 59,05%/30,48%

 

So I conclude that my code for generation is not taking very long, but it is causing minecraft to do something very timeconsuming, the problem is I don't know what!

I'll post my code here and would be very happy if you could take a look and maybe you will find some stupid mistake of mine, like forgetting to generate a light map or something.

 

PlanetoidChunkManager:

http://pastebin.com/VEemPii5

 

Planet:

http://pastebin.com/2jXeqncJ

 

I hope you can find something

 

[TheGreyGhost]

Hi

 

Do you have your code on GitHub or similar?

 

If so, I could download and run it with my profiler to see if it helps.  (Will take a few days, I have limited time at the moment)

 

-TGG

[TeNNoX]

Hi

 

Do you have your code on GitHub or similar?

 

If so, I could download and run it with my profiler to see if it helps.  (Will take a few days, I have limited time at the moment)

 

-TGG

 

Sure, I have it on Bitbucket (also via git, but private repos are free). I tried to make the repository public, but I am not sure if it worked.

If you have a better idea, I would be happy to hear

http://goo.gl/18KcJD

 

You can take your time, I just hope you will find something.

 

-Greetz, TeNNoX

[TeNNoX]

Would be nice if you could notify me if the git pull works ...

[TheGreyGhost]

Hi

 

After spending a couple of hours using VisualVM to trace things through, it looks to me like the massive lag is caused by all the block and sky light recalculations that take place.  Every time the lighting for a given block needs to be updated, it spends a long time cascading the changes to all nearby blocks.  This becomes very costly very quickly.  The reason it's so bad for your planetoid is because normally the world is almost all sky right down to the ground, then beneath the ground the blocks are usually solid and there are only a few caves open to the sky.  In your case, your whole sky is effectively "underground" with lots of "caves" open to the sky, which means that the skylight has to propagate itself sideways from the columns which are directly underneath the sky.

 

I think the best way to speed it up is to make sure that your chunk provider makes a good approximation for the initial skylight map.  The default vanilla one you use,

chunk.generateSkylightMap(); in PlanetoidChunkProvider.provideChunk()

does a great job down to the top surface and it's rubbish underneath that.

Based on your knowledge of where the Planetoids are placed, you can easily initialise the Skylight of the air underneath the planetoids based on a simple non-iterative formula in 2 dimensions instead of three (imagine looking down from the top - a circle which is bright at the edges, tapering to dark in the middle.)  You can then generate vertical columns of skylight underneath the planetoid based on this circle, perhaps with tweaking for planetoids which overlap.  I think that a good initial approximation will help a lot.  You might be able to get it even better (eg the few layers of air underneath the sphere) if you let vanilla calculate the light map for a variety of planetoid sizes, then dump it to disk and make a lookup database of initial skylight against planetoid size.

 

This is all guesswork since I haven't tried it myself, but I'm pretty confident that's the problem.  I tested it by making all your planetoids spawn as glass blocks (which are transparent to skylight, so the initial skymap is good) and it was very fast.

 

-TGG