Paper: Possible performance regression in recent versions

[jordanwilliams1]

15-20 players online. 1-2k chunks loadded 1-2k enties. Even put view distance all the way down to 3, stopped all mobs. still the tps was fucked. Even looked at the cpu and it seems fine... Switched to spigot after testing the latest verison of spigot and a few released before the new release of paper. Spigot is working "ok" at a 17-18tps at 20 players. 5k chunks loadded, with 5k entites.

Here's the timings from paper during the lag:
https://timings.aikar.co/v2/?id=7a20be1490254bb48a8b31d2071a9efa

[jordanwilliams1]

Server was running on i7 4790k dedicated to itself. CPU is 100% fine. Spigot is running a bit better with the lag. 17-18tps at nearly double Entites / Chunks than on paper

[AlfieC]

Learn to read your timings - it's CraftBook.

EDIT: and hoppers!

[jordanwilliams1]

We've removed Craftbook after looking at the timings. Made nearly no difference. As for hoppers not much we can do about that at all. Was running 100% fine before we updated to latest paper spigot version :(

[jordanwilliams1]

Took a timings from normal spigot.
https://timings.spigotmc.org/?url=voteguvelu

world - tileEntityTick are high and causing a lot of server load, This wasn't a problem before. Has anything changed in minecraft in the past few weeks releated to this?

[zachbr]

You say the "new version" is causing lag, but you don't tell us which version you came from.

So the metric is nearly useless.

[BlackBeltPanda]

I have the same problem.
After updating from 819 to 885, I'm getting lots of lag from tileEntityTick.
Downgrading also didn't help me.

https://aquifermc.org/threads/major-lag-after-updating.333/#post-2074

[jordanwilliams1]

Sorry, I'm not sure what version i came from. I Beleive it was from around build 800

[BlackBeltPanda]

Here's a bit of a longer Timings report for reference: https://timings.aikar.co/v2/?id=2a7cb443b57c41a5a9a01664a7723e78

[TNTUP]

@BlackBeltPanda Noticed this issue aswell, myself its hoppers issue, but even with the player which was causing it was gone for the day so his area wasn't loaded but somewhere else still lags the server. Everything was fine in 842, rn at 885, I'll go look with 887 later.

[Talabrek]

I have also been experiencing terrible performance issues lately, so I am glad I came across this issue report because I thought it was a plugin issue and have been going crazy trying to find the source. I just now used my test server to try out different Paper versions and I was able to eliminate my lag problem. Note that the testing was done with only me on the server and I was standing in a location that loaded chunks with a lot of blocks, especially hoppers (about 2,100+ of them). Here is what I found:

Running Build #887 I was getting single digit TPS immediately after logging in.
I downgraded to build #839 and TPS held steady at 20. No lag issues.
Upgraded back to #887 just to be sure and got single digit TPS again.
I changed "max-auto-save-chunks-per-tick" in the paper.yml to 1.
I ran the server again on #887 and the lag was gone, but the performance seemed slightly worse than #839.

Here are the timing reports:

887 (max-auto-save-chunks-per-tick at default)
https://timings.aikar.co/v2/?id=427315a5ddf54d85b3bfddc2979230d0&section=all

839
https://timings.aikar.co/v2/?id=f46c45f753e34b2d99e74cc05c505e74&section=all

887 (max-auto-save-chunks-per-tick: 1)
https://timings.aikar.co/v2/?id=04a3eab680a84798958676a6a3140e74&section=all

Hopefully this helps someone, but I can't say if there will be any negative effects from setting the auto save chunks per tick to a low number.

[Talabrek]

@BlackBeltPanda Try removing the React plugin and using version 839.

[RoboMWM]

Since all of you who are complaining have issues with tile entities, try build 882, the last build before Paper's TE fixer was removed - apparently whatever TE fixer spigot has isn't cutting it.

[RoboMWM]

@Talabrek

887 (max-auto-save-chunks-per-tick at default)
https://timings.aikar.co/v2/?id=427315a5ddf54d85b3bfddc2979230d0&section=all

This one does not have a graph. I'd also suggest longer timings.

[TNTUP]

Using @Phoenix616'S LWC fork and I've disabled autosaving to 0 and using MCMA2 /save-all schedule each 15 minutes. I'll try reenabling autosave tomorrow. TPS are fine on #885 (no downgrade was done)

[BlackBeltPanda]

Tried 882 but still ended up with a bunch of lag around the 5 hour 40 minute mark.
Timings: https://timings.aikar.co/v2/?id=9badc0564fa346a78bc018ff33335c30

Edit: It's always around the 5 hour 40 minute mark for me.

[TNTUP]

I guess i'm magic, because my TPS are fine (I got 16 TPS but it got back to 18) https://timings.aikar.co/v2/?id=61f7f57ff1fe4f3c881cb276b948a599. Guessing my issue on my side is solved. Probably my LWC build I had issues. Idk for the others what is the culprit of those bad TPS

[RoboMWM]

@TNTUP and can you try with autosave turned back on (and disable MCMA's save script)?

[TNTUP]

@RoboMWM I'll try on the next reboot with autosave enabled (MCMA script disabled)^^

[jordanwilliams1]

@BlackBeltPanda Try to use normal spigot and check your tps. It improved mine. Haven't gone below 17tps yet. I Had 1 issue but I Think that was my fault.

[Talabrek]

@BlackBeltPanda

Looks like DiceFurniture is causing some lag for you, but I noticed you are using the latest version of uSkyBlock so I think the main source of TPS loss might be there. The problem is related to the feature that uses signs to let you complete challenges from chests. I personally don't use this feature on my server so I don't know the specifics, I just know that it uses the InventoryMoveItemEvent, so I cut that section out and saw a significant increase in performance.

If you don't use this feature, check out my uSkyBlock fork at https://github.com/Talabrek/uSkyBlock for the change I made or you are free to download my custom version at http://192.169.80.50:8080/job/Talabrek%20uSkyBlock%20Repo/ to see if it helps with your performance issues. Note that there are some other changes in my version that fix some NPEs and purge invalid UUIDs that I think are caused by switching between offline/online mode so use it at your own risk because it might remove files you don't want removed (backup first).

[Talabrek]

@jordanwilliams Have you tried switching back to the latest paper build and setting max-auto-save-chunks-per-tick: 1 (or disabling it) in the paper.yml? You mentioned tickTileEntity is giving you problems now, and looking at your timings it appears to come from hoppers. Paper has a lot of hopper optimizations that Spigot doesn't have so I think you will get better performance on Paper with a low max-auto-save-chunks-per-tick setting and push-based hoppers enabled.

[RoboMWM]

max-auto-save-chunks-per-tick: 1 (or disabling it) in the paper.yml?

Not gonna do anything (significant). https://github.com/PaperMC/Paper/issues/435

If you want to test with autosave off, set ticks-per.autosave in bukkit.yml to 0.

I'm curious about TNTUP's results, as he went the "disable autosave" route (as well as using a different build of LWC, so we'll hopefully find out the results soon after he re-enables autosave).

[Talabrek]

@RoboMWM

Not gonna do anything (significant). #435

Check out his original timings again. "World Save" accounts for 20% of his total processing and 27% of a tick, which is similar to the timings you yourself posted in #435 and similar to what I was experiencing. He was using 885, a post-fix build, so he shouldn't be seeing those kind of numbers for the World Save.

Maybe some other factors are in play here, but like I said before I was having the same issue on build 887 and setting max-auto-save-chunks-per-tick: 1 helped a lot without having to completely disable it.

[RoboMWM]

Ok, but my point is that specific config option does not do much itself. Autosave on means it runs every tick, no matter what that setting is set to. That only controls how many are saved when chunks are due for a save on a particular tick.

[jordanwilliams1]

@Talabrek my TPS is currently fine on spigot at the moment. I Will probably switch back in a few weeks, Hopefully by then the problems will be fixed.

[aikar]

@RoboMWM the way you worded that can be taken incorrectly.

When auto save is on, it doesnt auto save every chunk every tick, it still saves to a schedule.

However most the timings linked here doesn't even show Auto Save -- it shows random plugins running slow. It's very important to understand that Minecraft Performance is not consistent! Just because you have 20 TPS today doesn't mean you will tomorrow on same build. Players can perform certain actions that abuse slow elements of plugins, and change your performance.

For the CraftBook users -- please ensure you are on the latest version. I reported an issue with CraftBook and chunk loads that was fixed and it may be your issue.

If someone can get me a new timings with 15+ minutes of data with auto save settings set to normal (please do not set max chunks to tick to 1.... that will essentially make auto save useless), that shows high world save, we can explore more.

But so far only 1 of the timings even show auto save, but the graph is bugged, and needed more data.

Please get 15+ min timings and ensure any external saving is TURNED OFF!!!!! (External saving will cause lag spikes in world saving! this is why we did this Auto Save work, to finally get rid of these lag spikes)

[Talabrek]

https://timings.aikar.co/v2/?id=43f512d6376c44ba9a5ff5143d9bcb50&section=all

Okay, this is on my test server, build 889. I deleted paper.yml, bukkit.yml, and spigot.yml to generate new ones and used all default settings. I also removed most of the plugins. This was tested in my skyblock world, and for the first ~10 minutes of the timings I am in a less populated area and auto-save is ~15% of the tick. At the end of the timings you can see where I went to the spawn area which is populated with a lot of hoppers/chests. I wanted to get a longer sample from that point but the server crashed soon after because it ran out of memory (total of 2G allocated). Every time I tried to get timings from a populated area I would crash fairly quickly, which is why my original timings were so short. Here are some of the crash reports:

http://pastebin.com/UYTqWTne
http://pastebin.com/UddbEpN1
http://pastebin.com/ZJVvuKXV

Setting max-auto-save-chunks-per-tick: 1 (which I suppose is the same as turning off the auto-save feature) gets rid of the problem. The problem also does not exist on build 839.

[BlackBeltPanda]

Updated Craftbook, uninstalled React, and set max-auto-save-chunks-per-tick to 1 and I get about 9-10 hours lag-free as opposed to the 5 I was getting previously. It does still lag after those 9-10 hours, though.
I'm having issues getting the timings, however, since they keep turning off on their own. >.<

[aikar]

Please update to latest. I added better timings around saving.

[aikar]

*and report new timings.

And black belt turn your timings on in paper.yml. Don't really need to have it off

[BlackBeltPanda]

The timings are on in paper.yml. Like I said, they just keep turning off for some reason.
I'll update and try to get new timings.

[BlackBeltPanda]

I managed to get a proper timings report this time: https://timings.aikar.co/v2/?id=3c77d5837396407eaaa8a577aaa27664

[aikar]

Timings show its not auto save wrecking you, its plugins.

In that timings, Furniture Maker is absolutely destroying you. 181k Block Physics Events per tick.

So far each of these timings are showing plugins and not our auto save changes.

those timings also have auto save turned off...

So, i'm going to close this until timings can be shown to be auto save related. Really suggested you turn it back on for data integrity of your server.

[BlackBeltPanda]

Didn't know auto save was off. Which setting is that and what's the default value?

[RoboMWM]

Which setting is that and what's the default value?

Bukkit.yml > ticks.per > autosave

Default value is either 6000 or 3000 iirc (value is in ticks).

[BlackBeltPanda]

Thank you. =)
Looks like I had Essentials setup to auto-save everything. Switched it to using Bukkit's autosave value, instead.

[aikar]

Also, chunks per auto save in paper world settings. You changed yours to 1, it should be 24.

[BlackBeltPanda]

K, I've got new timings with auto save on: https://timings.aikar.co/v2/?id=b16dd8db1d064260aad8dbe367ed887a&section=all

The lag isn't nearly as bad as it was before and I know a lot of it is coming from the FurnitureLib plugin, but I am seeing a bit from World Save, now. Not sure if it's a normal amount or not.

[Talabrek]

Okay, I have made three more sets of timings. These were all done on a server with no players and a set amount of chunks around the world spawns loaded.

The first set is from build 892 with autosave enabled and set to default values (6000 in bukkit.yml and 24 in paper.yml). https://timings.aikar.co/v2/?id=454b81cdab0840b197d5ffb56b088ea0&section=all
The first part of the timings is without my skyblock world, near the end you can see where I loaded the skyblock world and the performance nosedives. I tried to get longer timings but the server would crash after a couple minutes at that point.

The next set is from build 892 with autosave disabled in bukkit.yml. https://timings.aikar.co/v2/?id=ab36f0085fc74ea989033234a043f30c&section=all
The skyblock world was loaded the entire time. Hoppers are a source of lag, as always, but the server is stable without autosave running.

The final set is from build 868, just before the autosave changes. Auto save is enabled in bukkit.yml and all other config values are set to default. https://timings.aikar.co/v2/?id=3422a003bb7e4aec8ac5eaa06c159e90&section=all
The skyblock world was loaded the entire time and Hoppers still account for a large amount of the lag, but autosave isn't having an impact.

It seems that a high hopper/chest count causes issues with the current method of autosaving that did not exist with the previous method.

[aikar]

On the pre update build, note that spigot has a bug that multiplies your auto save interval by 4, so its 4x slower than what ever you configure it...

So if your configured to 5 mins, your auto save rate is actually 20 minutes. You'd need over 20 minutes of timings to see it, and the chunk would have to stay loaded for more than 20 minutes.

In other words, the only reason you do not have lag on the older builds is because the auto save logic is fundamentally broken.

And of course, turning it off will save the lag too (so it only saves on chunk unload)

So ultimately, the change is good, its just you cant use default settings (and we can consider changing defaults)

1st) Increase your auto save rate for skyblock specifically, to say 12000 (10 mins) - theres another config in the paper world settings thats -1 by default for it, set skyblocks to 12000. 2nd: Lower your max chunks to be 12 instead of 24.

This should keep you stable. Please report a timings report with 20+ minutes of data in it with auto save on those settings for us and we can consider if defaults should be changed for max per tick (vanilla chose 24, and we know vanilla is usually not the best decider in performance)

[aikar]

Ok, after experiencing serious crashes on my own server, I did some really deep study and found chunks were saving extremely faster than it should've been.

Fixed in build 906 (as well as another hopper oriented improvement!)