onChunkLoad handler takes a lot of processing time

[iNko97]

Hello Dan, I was testing lag sources in my server, and I noticed with spigot timings that CropControl's onChunkLoad event handler is very heavy on it, do you have any suggestions on how to fix that?

Inko

[ProgrammerDan]

Is it clocking on the mainthread, e.g. slowing the primary tick? Or just off in its own world/thread chewing up time?

Other then that, describe to me somewhat the system that is running (how much memory, how many threads) so I can better understand possible bottlenecks. Once I have that, I can look at the code and see what might be the cause.

[iNko97]

According to spigot timings, it is slowing the primary tick: (Timings extrapolated out of an hour of server runtime)

Minecraft::Full Server Tickcount(731) total(100.00% 139.19s, 380.82% of tick)avg(190.41ms per - 190.41ms/1.00 per tick)
Minecraft::world_name - doTickcount(731) total(61.01% 84.917s, 232.33% of tick)avg(116.17ms per - 116.17ms/1.00 per tick)
Minecraft::world_name - Chunk Tickscount(730) total(30.77% 42.833s, 117.19% of tick)avg(58.67ms per - 58.59ms/1.00 per tick)
Minecraft::world_name - Light Chunkcount(68779) total(30.12% 41.926s, 114.71% of tick)avg(0.61ms per - 57.35ms/94.09 per tick)
Minecraft::world_name - Light Chunk (SELF)count(68779) total(29.94% 41.671s, 114.01% of tick)avg(0.61ms per - 57.00ms/94.09 per tick)
Minecraft::world_name - ChunkIO Stage 2 - Post Loadcount(72) total(0.13% 0.176s, 0.48% of tick)avg(2.44ms per - 0.24ms/0.10 per tick)
Minecraft::world_name - chunkLoad - Postcount(19359) total(23.07% 32.107s, 87.84% of tick)avg(1.66ms per - 43.92ms/26.48 per tick)
CropControl::Event: c.p.m.c.h.CropControlEventHandler (ChunkLoadEvent)count(19359) total(21.64% 30.126s, 82.42% of tick)avg(1.56ms per - 41.21ms/26.48 per tick)

When there are few players on the server tps is not impacted that much, but I am worried in prospect of my entire playerbase joining it and roaming chunks...

The system is a dedicated server with 8 core cpu and 64gb (10gb ram dedicated on this server). (Some other server runs on the cpu, but that is not cause of worry, since it is not ever fully utilized).

If I have been unclear or you need more specifics just tell me :)

[ProgrammerDan]

Nah, that's perfect. I'll check into it. The real work of chunkloading is supposed to be asynch, so something's screwing up somewhere :)

[iNko97]

Thank you!

[ProgrammerDan]

Question -- is your database on the same machine as the server?

[iNko97]

No it is not, but it is hosted in the same place, so it would take it less than a couple ms to get the informations to each other. (Tested it, on average it takes 0.127ms)

[ProgrammerDan]

Yeah, it probably just mildly exacerbates the underlying problem, if anything.

I've confirmed that those load sequences are synchronous. It might take me a little bit to fix this up for you, but I'm excited someone is using it heavily enough for this to be a problem. Bear with me a bit -- what's your timeline for adding more players?

[iNko97]

I was planning of making them join en masse on this weekend, but I can delay if it is necessary (In any case I can temporarily force little chunk loading by reducing viewdistance to the bare minimum).

I love cropcontrol because it allows me to revive something that was never rewarding in minecraft, it always seemed to me that (resource-wise) mining was the only rewarding thing that a player could do in the world. Thus the idea to tie mass experience production to cropcontrol's drops :P

[ProgrammerDan]

Yeah! That's the nucleus of the idea. I'll see if I can prioritize this fix for you then. I can't promise, but I'll give you an up/down on it Thursday night.

Basically what's happening right now is, first load of all chunks into memory is going to be synchronous and slow. The good news is unloading is asynch and delayed, so it's just front-loaded. My current thought is to "immediately" load only the chunk the player is standing in, then queue up the rest of the chunks. This isn't ideal, because BUD events occur within any chunk at any time while loaded, and CropControl pays attention to some of them... so there might be lost tracking for certain types of edge case physics breaks by making these secondary loads asynchronous. Probably "worth it" though in terms of performance gains.

The only other thought I had is once I do make this asynch, you'll see heavier simultaneous load (I'm going to have a shared queue & a worker pool to deque) on the database; you'll want to check your config to be sure you're allowing 200+ connections to the DB, then increase the size of the connection pool in CropControl's config, so that as multiple players move around there is reduced contention on a "small" pool of connections, all trying to load chunks.

tl;dr probably will want to increase your database connection limit and double or triple the poolsize for CropControl.

[iNko97]

Hey Dan, any news on the fix?
(I set the pool to 400, should be fine when update rolls out)

[ProgrammerDan]

Sorry for the lack of activity! My weekend plans didn't work out like I thought they might when I first replied. This is still on my radar, I'll try to work on it near-term.

[iNko97]

Hello Dan, is there any chance this will get fixed anytime soon?

Inko

[ProgrammerDan]

Clearly, this fell off my radar entirely. I'm not sure, I haven't been very active in this space recently. I've got several other people asking me to fix other things in other plugins as well, so I really do need to allocate some time to work on these and other outstanding issues.

[iNko97]

More on this problem I was able to get by observing debugs: apparently the lag is not caused by chunks being loaded, but by chunks being added to the database when they first get loaded.
Cropcontrol was not present when the world was generated, and probably that made this problem more relevant. I will look into ways of chunk loading every single existent chunk to make cc create the db entry.