Paper: Strange/incorrect timing reports

[TheoRetisch1]

I have strong performance problems since the update from 1.12.2 to the 1.13.2 and can't identify the reason correctly. The timing reports are also different every time. Sometimes I have 8000 boats, sometimes 6000 llamas and sometimes 10000 cats. They change suddenly and don't even find themselves in the timing report regions, not to mention on the server itself: https://imgur.com/a/cP3JdFH

Do you have an idea where the strange data under "Minecraft::weltn - tickEntities -> Minecraft::weltn - entityTick" come from?
Of course I am also very thankful for hints for the cause of the TPS problem xD.
The deletion of all armorstands is not a solution, unfortunately.

Timings: https://timings.aikar.co/?id=fbd0d411c55a42eda2a6e05790e4cf7a#timings

[aikar]

can you check your logs for any reports of timings stack corruption?

I agree something does feel off.... but I seriously can not replicate anything wrong in local testing.

[TheoRetisch1]

Thanks for testing! Well, I can't find any errors in the log. There are only a few plugin errors. There are the following two errors, which also contain the word "timings":
https://pastebin.com/kpASm0W5
https://pastebin.com/r56YVikX
The ChestShop error is due to a sign that had to be rewritten after the update. The
AutomaticInventory error is a plugin bug that has not yet been fixed.
I can't imagine that these bugs are responsible for changes in the timings.

With fewer players online there are less performance drops and in the timings no unrealistic values can be detected. However, I had this problem over the weekend over and over again sporadically across server restarts. I guess I just have to keep watching to get to the bottom of it and report here.

But do you have any idea why the performance drops occur? Except for a few armor stands I see nothing system critical? On version 1.12.2 everything went so well.

Here is a current timing report with the same setup, but without controversial details:
https://timings.aikar.co/?id=d16869a7f297416087eb4e0c1c9f0f29

[TheoRetisch1]

The problem with the strange entity information is back. Meanwhile there was a restart. The only error I could find regarding the timings is still the one from AutomaticInventory: https://pastebin.com/mhDXWSHg

Timings: https://timings.aikar.co/?id=50fcbb1cf61c4c9c85fa46726e37f361

[Cryptite]

We see strange behavior related to entities as well. If I can catch it I'll try to upload a timings with a requisite YK snapshot.

Here's a recent one of ours https://timings.aikar.co/?id=a4ab0a2b375b4423a3a90e56870a9014

[TheoRetisch1]

I still have the same problem with the new paper version. Depending on the time span you set in the lag-view, the timings will show correct values, 5000 donkeys or 9000 donkeys:
https://timings.aikar.co/?id=f70d9329260a4ab6be0cbd0df2932015#timings

[aikar]

well, I can't see how the problem could be incorrect timings.
There's no way this can happen with latest timings code.

What this implies is that there is yes indeed 9000 donkeys being timed - the question is.... why are they timing them when they don't APPEAR to be in the world.

I have suspicion that the server isn't removing entities from the world correctly so you have invalid entities remaining that shouldn't be there, taking up tick time.

[ItsFlare]

I have suspicion that the server isn't removing entities from the world correctly

We've been observing this issue with amounts never even possibly attempted to be spawned.
Perhaps there is some duplication going on, too!

Edit:
On the flip side, we would expect a lot more ghost entities from certain types, such as Guardian, in chunks with farms of such

[TheoRetisch1]

Thank you for the evaluation! But what is the consequence of this statement? How can I find out if the server does not handle the entities correctly? How can I help solve this problem? And what can I do to get rid of the lags?

[Ajaxan]

Just to add some more data to the issue and confirm another occurrence of it, our server is also experiencing this issue with tickEntities. It should be mentioned there is a consistent ArmorStand lag issue as well and that one we actually know the cause of and are working to fix it separately. Anyway here a few timings reports.

https://timings.aikar.co/?id=a064406dbac04d39a748441a3fa4f036
https://timings.aikar.co/?id=a06b3a4cb50d46d1bcaf7a67364efc89
https://timings.aikar.co/?id=e24d81c663fe4cdfb7c04fd0ed3e87cc

I noticed the talk of timings being inaccurate, and they are but they aren't? 5 TPS should make the server basically unplayable from everything I seen and experienced up to this point but our players report only minor lag. That said if you pay attention to how fast tasks run and time moves it is definitely moving at 1/4th the normal speed. So very odd to say the least.

[Ajaxan]

electronicboy requested I add this flag in the startup script: -Ddebug.entities=true

Using this: https://github.com/LXSN/Paper/blob/master/Spigot-Server-Patches/0291-Add-Debug-Entities-option-to-debug-dupe-uuid-issues.patch

I searched some of the keywords in the logs after a day of running with the flag to find debug messages. I found something, but I'm not sure if it's related. There are four Items, Paper, Written Books, Crafting Tables, and Compasses that throw this error occasionally. As the error with TickEntities occurs with a huge number of different Entity Types not contained within that short list I'm lead to believe it's unrelated. Hopefully eliminating this helps in some way.

Here is a pastebin of the error. The only difference between them is the date and entity types mentioned above. Is there any other tests that I could try to help figure out this odd EntityTick bug?

https://pastebin.com/nU0CC1mN

---

On a side note, here is another two timings reports without the ArmorStand lag of the previous ones (finally got around to fixing that).

https://timings.aikar.co/?id=acc606a5b45745e2bbe14c2ea05b0aae
https://timings.aikar.co/?id=ad16129f77cd4df1a8634aefe862828b

[TheoRetisch1]

Uhh how did you fixed your armorstand performance problem?

[Ajaxan]

It was a custom farming plugin I made that uses armorstands to make crops. Turns out players liked it and made thousands and thousands of crops.. Which meant thousands of armor stands loaded all the time... Just a bit much for our server to handle.

---

Did some more looking, this bug occurs even with a clean server. The thing is it's just less noticeable. Check out this timings report on a clean paper server with no plugin running on my local machine.

https://timings.aikar.co/?id=f18de0951121493a8331f81d2ddf52c9

Now the tickEntities are buried in this report, but if you find them in the list, and check it out I have EnderDragons taking 1.3% of the tick... Which is odd because this is a fresh server with no plugins. Most importantly it's taking much more time than any of the other entities which mirrors the situation with the full server at a smaller scale.

[aeonlamb]

I'm noticing this problem on my server now too. Only became apparent today, since I recently updated my server to paper 612. I started getting a lot of lag out of nowhere, down to 10 tps or so, and tried checking timings, but it's really difficult to discern what's causing it since the timings seem to be counting things incorrectly. Here's a timing report: https://timings.aikar.co/?id=2ed759d4356d436d9c6431ef3caabe73

I've noticed it saying there's 4000 armor stands loaded, then 4000 experience orbs... I've checked multiple times with /paper entity list and there's not nearly that many of either of those entities, it's something like 40x more armor stands than are actually loaded. Really strange.

[aikar]

@aeonlamb where do you see 4k armor stands or orbs in that report? I cant find it. that report looks unaffected.

[KarlOfDuty]

We have seen the same since a build somewhere in the late 500s, I have not noticed it recently but I will provide a report here if I spot it again. It is not a constant issue for us but once it happens it seems to remain until the server is restarted. (Although it will switch between what entity type is found to randomly have millions of entities every few seconds during the anomaly)

[Ajaxan]

@aikar Not sure if it's exactly the answer to the question you're looking for but the lag from armor stands and experience orbs can only be soon by looking at specific time periods of the whole report. Like moving the min and max slider over by two positions showed the armor stand lag. Left in the default position massive spider lag is showing up on aeonlamb's report. Apologies if this isn't what you meant.

[aeonlamb]

Yeah, with the slider on the 3 right-most segments, it shows 4,000 experience orbs per tick under "entityTick". There definitely wasn't that many orbs, weird stuff.

[TheoRetisch1]

I appreciate your efforts! But unfortunatly I am still facing the same problem with the latest version 616. This time there are 7000 EntityHorseZombie xD: https://timings.aikar.co/?id=b429c0b55d6f4ce4b10bd98b8b48472a
By the way I got rid of the plugin error shown above.

[ArtNRG]

Is it still an issue in the latest build? I'm on paper build 571 because of this.

[TheoRetisch1]

I can confirm it for version 1.13.2 build 627. So yes it's still ongoing.

[TheoRetisch1]

The problem did not occur in my test phase from Paper 1.15.2 build 207 - 231 #closed