FramedMapUpdater takes 628% of server tick

[TheNety]

BkCommonLib version:

1.14.4-v1

Spigot version:

Paper 1.13.2

---

Problem or bug:

BKCommonLib takes too much of server tick, to be specific, 628% of tick takes BKCommonLib::Task: com.bergerkiller.bukkit.common.internal.CommonMapController.FramedMapUpdater (interval:1)

Expected behaviour:

It doesn't take so much of tick

Steps to reproduce:

If it could be caused by that, in the time of timings was collecting data, I used plugin ImageOnMap ( https://www.spigotmc.org/resources/imageonmap.26585/ ) and was placing and destroying a lot of item frames in a moment.

Screenshot of timings:

[bergerkiller]

Hmn, what is 'a lot of item frames'? How large of an image display do I have to create for it to create such a lag spike? It might be caused by something specific ImageOnMap does, like adding and removing a lot of entities rapidly.

[TheNety]

Again tried it, without using ImageOnMap and it looks like it's happening because of fast placing and destroying item frames. https://i.imgur.com/cpQ549N.mp4 Looked to the timings then and it was high

[bergerkiller]

Thank you! I will look into what I can do to either debounce this so it doesn't do so much processing when an item frame changes frequently, or that the time spent processing goes down.

The processing it does is to check whether there are neighbouring item frames, and with a lot of item frames on the server this can be costly when executed often.

[bergerkiller]

Hmn it certainly doesn't occur with just a few entities on the server and a single wall of item frames. Any estimate how many item frames you have on the server on the world on which you did this placing and destroying/changing? And how many other entities? There's no good way to calculate this using vanilla commands, so hopefully you have some plugin that can show that for you like a lag monitoring plugin

[bergerkiller]

I did a little commit history checking and found one commit that is in the v2 snapshot that is not in the v1 release that may seriously impact the performance of what you were experiencing (caches the item frames it knows about per world, rather than recomputing it): https://github.com/bergerhealer/BKCommonLib/commit/2589f029f1999962d76774ab2b2e89df557ce5ec#diff-3a1b13a14baf065f8df14eb11a5d8fc3

It is worth trying the v2 snapshot to see if there is any change in lag https://ci.mg-dev.eu/job/BKCommonLib/658/

[TheNety]

So I tried the latest dev build (build 658) and was walking for like 5 minutes around my base (so I wasn't placing and destroying any block etc. just walking and flying) and the timings looks like that

In the area I was moving there's exactly 60 item frames in total and all of them has a image from ImageOnMap in them. (If it loaded my meme wall so the number is 778 xd but I don't think it loaded it during that time)

[bergerkiller]

@Nety01 I couldn't really reproduce it, but I did find a possible explanation for the high timings. When item frames are placed at a chunk border, it has to load the neighbouring chunk in order to detect a full display. This may be causing some unlucky performance issues in your case. I've added some additional timings to rule this out/in.

https://www.dropbox.com/s/7qrvu5lbcxxhx98/BKCommonLib-1.14.4-v2-SNAPSHOT.jar?dl=0

Can you run another timings and send the report? It should show additional entries 'chunk_load', 'update_frames' and 'refresh_displays'

[TheNety]

Yeah sure. New version, new timings.

[bergerkiller]

Sorry for the back and forth, one more version to test. Ive littered timings all over the place to figure out where so much time is spent, since it wasn't the obvious one (chunk loading).

https://www.dropbox.com/s/7qrvu5lbcxxhx98/BKCommonLib-1.14.4-v2-SNAPSHOT-timings2.jar?dl=0

Hopefully this will pinpoint exactly what steps take long. Thanks for helping me out in finding the root cause by the way! :)

Note: 20% tps peak is still high for chunk loading, I'll likely make that portion asynchronous once the main issue is resolved

[TheNety]

Yea I'm happy to help to get that fixed.

[bergerkiller]

woah so in the span of 9 tick updates it had 4299 item frame neighbour detections. Thats pretty crazy. Unless theres thousands of item frames on the server, that cannot be right. Ill look into it

[bergerkiller]

So I'm noticing something in both previous timings reports:

In that short timeframe 3000 new entities are added. Are these all item frames? Is it possibly part of your meme wall? Or is something triggering the rapid spawning and respawning of a large number of entities for a couple ticks?

The map UUID recalculation logic is truly executing 4000 times in just 9 ticks, and every tick it can at most execute it once per item frame entity. I can spot some room for improvement in the algorithm, but it's still a lot of entities all at once.

[TheNety]

I don't think it's all item frames, I wasn't near to so much of item frames, except the meme wall. Something triggering rapid spawning and respawning a lot of entities, I don't have anything like that there as I know. But I also have there a lot of commands block (that weren't activated) and holograms (armor stands).

Maybe one way of "fix" would be the option to disable that item frame check in config?

[TheNety]

Well, if it's not needed of course. I use it for LightCleaner plugin.

[bergerkiller]

A config option might be the only way to work around it for now Im afraid. I prefer not to do this because right now, there is no config.yml for bkcommonlib, and it would be nice to keep it that way.

I'll first give optimizing this a try with below 2% tps peak as a goal, if I can't make that happen by optimizing the neighbour detection logic then I'll add a config.yml with an option to turn item frame handling off.

[bergerkiller]

I've made further changes in what I suspect were the reasons for spending so much time updating item frames. This was:

• Eliminate use of BKCommonLib's NBT API in critical code, using NMS directly instead
• Avoid temporary objects/wrappers being created in some places
• Cache the item frames mapped to facing + coordinate, so not all item frames of a world need to be iterated to find clusters

There's a reduction in time spent in local testing, but since I never get such extreme results like you did, I'm not sure if this is enough to do it.

Have a try: https://www.dropbox.com/s/4bl6vsay9l2qnxt/BKCommonLib-1.14.4-v2-SNAPSHOT-timings3.jar?dl=0

If this still doesn't fix it, I'll add a config.yml + option so this can be worked around.

[TheNety]

Hmm looks much better than before anyway

[bergerkiller]

I have a version ready that allows you to disable all this frame tiling logic, but I first need to test these changes on all versions of minecraft to make sure nothing broke by accident.

# Whether multiple item frames next to each other can merge to show one large display
# This allows Map Displays to be displayed on multiple item frames at a larger resolution
# The tiling detection logic poses some overhead on the server, and if unused, can be disabled
enableItemFrameTiling: true

[bergerkiller]

Committed the changes, you can try the build version here: https://ci.mg-dev.eu/job/BKCommonLib/659/

[TheNety]

Alright thank you. So this shouldn't do any visible changes right? Also can I disable it when I use this plugin for LightCleaner?

[bergerkiller]

The frame logic is only used by map displays, which isn't used by light cleaner. It also won't affect the ImageOnMap plugin, since it doesn't use BKCommonLib's map display api for rendering images.

The only plugin that might require this feature is https://www.spigotmc.org/resources/maplands.46404/

[bbayu123]

Should I assume this is resolved?

[TheNety]

For me yes

[bbayu123]

Nice, then I shall close this.