CRAFTBOOK-3201 - Reported by kikelkik

At first thanks for updating this amazing to MC1.10!
Unfortunately since updating the server to 1.10, we're having some tps drops obviously caused by CraftBook.
Here's the timings on 1.10 server: https://timings.aikar.co/v2/?id=107a9ab286f649d19475fb985e0d5e4c
Consider that you can pop up the categories in 'Lag View' multiple times. So if you click on 'Minecraft - Bukkit Scheduler' (which is most percentage of tick on the right side) there's CraftBook::Task: com.sk89q.craftbook.core.st.MechanicClock (interval:2) on top and if you pop this up, CraftBook::Event: c.s.c.m.i.ICMechanic (SelfTriggerThinkEvent) has got ~300% of tick.

For comparison here's the timings on the same server with mc1.9.4:https://timings.aikar.co/v2/?id=221d371f74f341e7a62a03cf37d17f67
where CraftBook::Task: com.sk89q.craftbook.core.st.MechanicClock (interval:2) does 'only' 20% of tick.

Hopefully you can figure out what've been changed in 1.10 to optimize the performance with CraftBook.

Comment by FatherWh0

http://prntscr.com/bsk2ax
http://prntscr.com/bskorj
I've been watching the timings on both my servers and I've noticed the chunks with quite a few ics are always at the top. In some cases these chunks are not populated during the time period covered by the timings. In one case the top region had not been visited by players in over 18 hours. It should not have been loaded. Basically, the chunks with ics have become self-loading.

Comment by me4502

The first WarmRoast report is definitely the issue inside of MC that's amplified by Spigot/Bukkit. Calling getTileEntities() on a Chunk is loading all nearby chunks. This isn't an issue that is fixable inside CraftBook, it's entirely inside CraftBukkit&Spigot

Comment by FatherWh0

Can/should this be submitted to Mojang? My servers need a solution other than disabling some of craftbook's best features.

Comment by me4502

I think it's more that Spigot improperly uses the new changes that have occurred in the game. It'd be better to report it to Spigot.

Comment by aikar

This isn't a "bug" in spigot. It's not loading neighboring chunks, but instead, loading the chunk its trying to act on.

It ultimately is the fault of this code: https://github.com/sk89q/CraftBook/blob/3.x/src/main/java/com/sk89q/craftbook/core/st/SelfTriggeringManager.java#L127

It's scheduling to process something on the chunk 2 ticks later, but you have no guarantee that chunk will still be loaded 2 ticks later.

When getTE is called, that getBlock call then re-triggers the chunk to be loaded.

Now, pre 1.9 we had the EmptyChunk system, which may or may not of 'squashed' this behavior by returning a dud chunk, but that's no longer the case and even then that was logically questionable.

The proper fix is to add

if (!chunk.getWorld().isChunkLoaded(chunk)) { return; }

at the start of registerSelfTrigger to avoid ever processing unloaded chunks.

Comment by me4502

Thanks @aikar, I've pushed a fix.

Comment by FatherWh0

Build #62
http://prnt.sc/bvl8ah

Comment by me4502

Ah good, that's looking much better in terms of CraftBook. That specific chunk load is being caused by Dynmap.

Comment by FatherWh0

Thank you @me4502 and @aikar.
Yes, dynmap is it's own monster.

Comment by me4502

That isn't caused by CraftBook, that's a known issue with the base game that is amplified in Spigot/Bukkit. It's been an issue since the first build of 1.9, but paper have been patching it, however it keeps regressing and coming back.

I'd make sure you're running the latest build of paper. If it's still an issue, I'll pass it on to Aikar.

Comment by kikelkik

Thanks a lot!

Comment by FatherWh0

I've been running into this also. Saw it in 1.9, then in 1.9.4, now again in 1.10 and 1.10.2.
https://timings.aikar.co/v2/?id=b7fdca129ffb489eb1aa7b8f0492242e

Comment by me4502

If you do a WarmRoast profile I can tell you exactly what it is, but it's most likely the spigot performance bug with chunks.

Using the latest build of paper is the most likely way to fix it.

Comment by FatherWh0

Running paper #809.
http://paste.enginehub.org/gQictv.report
https://timings.aikar.co/v2/?id=8b3e24e489a34a75b8eef514a39fe4a9

Comment by me4502

Could you please run WarmRoast rather than Timings, it's more accurate and gives more information.