search

PaperMC / Paper

The most widely used, high performance Minecraft server that aims to fix gameplay and mechanics inconsistencies
https://papermc.io/
Other
10.04k stars 2.34k forks source link

Timings v2 misattributing time to a randomly selected entity? #2489

Closed totemo closed 4 years ago

totemo commented 5 years ago

What behaviour is expected:

I expected the per tick count of Minecraft::tickEntity - nms.<EntityType> to be no more than the number of entities of that type in the world, counted by a plugin. That is, I am expecting timings to show that Minecraft::tickEntity() is called at most once per entity per tick, for each type of entity.

What behaviour is observed:

Expanding Minecraft::world - tickEntities > Minecraft::world - entityTick the top row there is Minecraft::tickEntity with a wildly inflated per tick count.

Some examples:

Interestingly enough, the top level timings row Minecraft::tickEntity doesn't show these crazy per tick counts, which is consistent with the idea that it is some kind of bug.

Steps/models to reproduce:

Normal server operation. Do a /timings report.

Plugin list:

Plugins (72): AdminHunt, BeastMaster, BlockStore, Checkpoint, CleanroomGenerator, CommandBlock, CommandHelper, Doppelganger, DVDA, dynmap, EasyRider, EasySigns, EntityControl, EntityMeta, GoneBatty, HelpHelp, HolographicDisplays, Hopperator, HyperCarts, Images, ItemLocker, ItsATrap, KeepBabyMobs, KitchenSink, LastSeen, LibsDisguises, LimitSpawnEggs, LogBlock, LolNeigh, LolNo, LuckPerms, LWC, MaskOfFutures, MobLimiter, ModMode, ModReq, Multiverse-Core, NerdAFK, NerdAlert, NerdBoard, NerdClanChat, NerdFlags, NerdList, NerdMessage, NerdPlot, NerdPoints, NerdSpawn, NerdStats, NerdUsage, NerdVisit, NerdyDragon, NoCheatPlus, OpenInv, ProtocolLib, RedstoneClockDetector, RFChairs, SafeBuckets, SafeCrystals, StandMaster9000, TPControl, Trampoline, TrancePing, VanishNoPacket, Vault, VehicleControl, VillagerUtils, VoidGenerator, WingCommander, WorldBorder, WorldEdit, WorldEditSelectionVisualizer, WorldGuard

Paper build number:

This server is running Paper version git-Paper-175 (MC: 1.14.4) (Implementing API version 1.14.4-R0.1-SNAPSHOT)

Anything else:

I don't know how timings is implemented in great detail, but I imagine it would have to bracket sections of code with start and stop functions for attributing the time to a particular category. It looks like it picks on a single entity type each time to attribute these large per tick counts, which might be caused by forgetting to "close brackets" on the last entity type processed.

The other possibility is that these entities really are being added to processing queues more than once, which would be fantastic from our perspective because fixing it would fix our entity lag. :smile:

galacticwarrior9 commented 5 years ago

Can confirm the issue exists on Paper 642 (1.13.2 ), this time with rabbits. I also can also confirm that I do not have 1,100 rabbits across my worlds.

https://timings.aikar.co/?id=2c469d747b98456ba828389798b864a5

aeonlamb commented 5 years ago

I've been having this issue for quite a while in Paper for 1.13.2 as well. Currently using build 641, been happening for months. It's made diagnosing lag issues with timings nigh impossible if the issue is entities (which it almost always is in 1.13)...

Here's an old timings report that illustrates the problem: https://timings.aikar.co/?id=e99a9151d0164b669654de837a7af9d4

Timings reports over 4,000 creepers per tick, but there's no way there was anywhere near that amount of creepers loaded. This can happen with seemingly any mob, I recall seeing thousands of chickens, thousands of sheep, etc etc etc... It seems very random.

totemo commented 5 years ago

I'll just pass this one on as a further debugging possibility.

One of our plugins is doing an oopsie on login that I need to fix. It strikes me that the timings stuff appears on the stack trace and that maybe not dealing with exceptions from plugins under some circumstances could be leaving timings in an invalid state.

2019-08-24 05:25:56 [ERROR] Could not pass event PlayerJoinEvent to TPControl v0.8.1
java.lang.NullPointerException: null
        at java.util.concurrent.ConcurrentHashMap.putVal(ConcurrentHashMap.java:1011) ~[?:?]
        at java.util.concurrent.ConcurrentHashMap.put(ConcurrentHashMap.java:1006) ~[?:?]
        at nu.nerd.tpcontrol.UUIDCache.clearUUID(UUIDCache.java:220) ~[?:?]
        at nu.nerd.tpcontrol.UUIDCache.updateCache(UUIDCache.java:200) ~[?:?]
        at nu.nerd.tpcontrol.UUIDCache.access$600(UUIDCache.java:32) ~[?:?]
        at nu.nerd.tpcontrol.UUIDCache$MyListener.onPlayerJoin(UUIDCache.java:295) ~[?:?]
        at com.destroystokyo.paper.event.executor.MethodHandleEventExecutor.execute(MethodHandleEventExecutor.java:37) ~[patched_1.14.4.jar:git-Paper-175]
        at co.aikar.timings.TimedEventExecutor.execute(TimedEventExecutor.java:80) ~[patched_1.14.4.jar:git-Paper-175]
        at org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:70) ~[patched_1.14.4.jar:git-Paper-175]
        at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:545) ~[patched_1.14.4.jar:git-Paper-175]
        at net.minecraft.server.v1_14_R1.PlayerList.a(PlayerList.java:191) ~[patched_1.14.4.jar:git-Paper-175]
        at net.minecraft.server.v1_14_R1.LoginListener.c(LoginListener.java:174) ~[patched_1.14.4.jar:git-Paper-175]
        at net.minecraft.server.v1_14_R1.LoginListener.tick(LoginListener.java:65) ~[patched_1.14.4.jar:git-Paper-175]
        at net.minecraft.server.v1_14_R1.NetworkManager.a(NetworkManager.java:256) ~[patched_1.14.4.jar:git-Paper-175]
        at net.minecraft.server.v1_14_R1.ServerConnection.c(ServerConnection.java:139) ~[patched_1.14.4.jar:git-Paper-175]
        at net.minecraft.server.v1_14_R1.MinecraftServer.b(MinecraftServer.java:1232) ~[patched_1.14.4.jar:git-Paper-175]
        at net.minecraft.server.v1_14_R1.DedicatedServer.b(DedicatedServer.java:417) ~[patched_1.14.4.jar:git-Paper-175]
        at net.minecraft.server.v1_14_R1.MinecraftServer.a(MinecraftServer.java:1075) ~[patched_1.14.4.jar:git-Paper-175]
        at net.minecraft.server.v1_14_R1.MinecraftServer.run(MinecraftServer.java:919) ~[patched_1.14.4.jar:git-Paper-175]
        at java.lang.Thread.run(Thread.java:835) [?:?]
Frogperson commented 5 years ago

We've been having this exact same issue for quite some time now on all versions of 1.14. A completely random entity is shown as taking up the most of our entity timings, and it changes depending on which 5-min interval you're looking at. I would be happy to supply some timings reports if it would help get to the bottom of this.

james090500 commented 5 years ago

The plugin issue @totemo has nothing to do with timings. looks like it's trying to put a null value into a hashmap. Speak to plugin author

galacticwarrior9 commented 5 years ago

@james090500 Could you explain further? How did you determine this, and which plugin authors should we be talking to?

electronicboy commented 5 years ago

Paper has had a technique to recover from issues around exceptions being thrown which would impact timings by winding up the stack, timings info might be out in those cases, but should never impact the count

I did fix an issue which would lead to a single entity being counted more than once, I don't see how timings could count an entity that isn't there, being that it's timing from inside of the tick loop itself;

There was a /paper entity list command added a while back, might be worth trying to compare that to what timings is recording, making sure to only compare what you're seeing with the last timing window

james090500 commented 5 years ago

@james090500 Could you explain further? How did you determine this, and which plugin authors should we be talking to?

Its your own plugin causing issues by the look

https://github.com/NerdNu/TPControl/

    at nu.nerd.tpcontrol.UUIDCache.clearUUID(UUIDCache.java:220) ~[?:?]
totemo commented 5 years ago

Yeah, I get that, I was just tossing exception handling out there as a possibility for the weird entity counts. There's certainly something going on there. And FWIW, in the intervening period, I fixed the NPE and the timings counts were still weird after that.

We're running EntityControl which does periodic scans to count entities and the counts don't concur with the timings facility shows in totals.

What I am seeing that is very strange is timings showing the total entity counts growing over time, massively. I'm almost afraid to ask, but here goes: is there code in Minecraft/Spigot/PaperSpigot that relies on weak references to chunks or entities for correctness such that any plugins that don't immediately release references might be causing issues. Again, I'm just spitballing it. AFAIK all of our plugins do not contain any such memory leaks. Trying to come up with wilder theories that might fit the observed symptoms.

What I see after three quarters of an hour of 30-40 players is upwards of 10,000 entities. EntityControl doesn't count anywhere near than many live in the world. Spawn limits are tuned way down, by the way,

I will play around with /paper entity list and see what I can turn up. Thanks.

totemo commented 5 years ago

Timings shows 12,000+ entities: https://timings.aikar.co/?id=07e35fe19c284e0892c763980a746ac2 Including misattributing 666 cats:

Although if I scroll the time period to 1:31 to 1:45, then the timings counts 1100 pufferfish instead. The final timing window says there are 351 skeleton horses.

The output from /paper entity list shows there are far fewer cats:

Total: 4043
1562: minecraft:item_frame
279: minecraft:zombie
263: minecraft:skeleton
232: minecraft:villager
222: minecraft:creeper
161: minecraft:arrow
159: minecraft:armor_stand
147: minecraft:sheep
127: minecraft:item
96: minecraft:chicken
79: minecraft:cat
62: minecraft:painting
54: minecraft:experience_orb
46: minecraft:salmon
41: minecraft:bat
40: minecraft:cow
39: minecraft:spider
38: minecraft:hopper_minecart
38: minecraft:tropical_fish
36: minecraft:horse
30: minecraft:wolf
29: minecraft:pig
27: minecraft:turtle
26: minecraft:player
17: minecraft:rabbit
17: minecraft:squid
15: minecraft:pillager
15: minecraft:slime
14: minecraft:trader_llama
12: minecraft:iron_golem
11: minecraft:chest_minecart
11: minecraft:drowned
11: minecraft:mooshroom
11: minecraft:zombie_villager
10: minecraft:cod
10: minecraft:parrot
9: minecraft:skeleton_horse
6: minecraft:donkey
6: minecraft:llama
4: minecraft:trident
3: minecraft:minecart
3: minecraft:witch
3: minecraft:zombie_horse
2: minecraft:enderman
2: minecraft:fox
2: minecraft:mule
2: minecraft:ocelot
2: minecraft:phantom
2: minecraft:pufferfish
1: minecraft:dolphin
1: minecraft:end_crystal
1: minecraft:endermite
1: minecraft:husk
1: minecraft:polar_bear
1: minecraft:vex
1: minecraft:wither
1: minecraft:wither_skeleton
1: minecraft:wither_skull
1: minecraft:zombie_pigman

My EntityControl plugin concurs:

Total: 4063, ITEM_FRAME: 1572, ZOMBIE: 283, SKELETON: 265, CREEPER: 230, VILLAGER: 230, ARMOR_STAND: 159, ARROW: 155, SHEEP: 147, DROPPED_ITEM: 123, CHICKEN: 91, CAT: 80, PAINTING: 62, EXPERIENCE_ORB: 53, SALMON: 46, TROPICAL_FISH: 42, BAT: 41, HORSE: 41, SPIDER: 40, COW: 39, MINECART_HOPPER: 38, WOLF: 30, PIG: 27, TURTLE: 27, PLAYER: 26, SQUID: 19, RABBIT: 17, TRADER_LLAMA: 17, SLIME: 15, PILLAGER: 15, IRON_GOLEM: 12, MUSHROOM_COW: 11, COD: 11, DROWNED: 11, MINECART_CHEST: 10, PARROT: 10, SKELETON_HORSE: 9, ZOMBIE_VILLAGER: 8, LLAMA: 8, DONKEY: 6, ZOMBIE_HORSE: 5, ENDERMAN: 4, TRIDENT: 4, MINECART: 3, WITCH: 3, MULE: 2, OCELOT: 2, PUFFERFISH: 2, FOX: 2, WITHER_SKELETON: 1, HUSK: 1, VEX: 1, PIG_ZOMBIE: 1, WITHER: 1, ENDERMITE: 1, POLAR_BEAR: 1, ENDER_CRYSTAL: 1, PHANTOM: 1, DOLPHIN: 1 Counted 1774 loaded chunks in 6 milliseconds.

Small variations in counts are because players move, mobs move/spawn/despawn and I didn't run the comands simultaneously, but over the span of a minute or so

/paper chunkinfo excerpt from the top 5 worlds (we have a few more with 81 each):

Total: 6813 Inactive: 5059 Border: 689 Ticking: 519 Entity: 546
Chunks in world_nether:
Total: 822 Inactive: 741 Border: 32 Ticking: 24 Entity: 25
Chunks in world_the_end:
Total: 495 Inactive: 414 Border: 32 Ticking: 24 Entity: 25
Chunks in arenas:
Total: 81 Inactive: 0 Border: 32 Ticking: 24 Entity: 25
Chunks in pve-events:
Total: 380 Inactive: 123 Border: 87 Ticking: 64 Entity: 106

Clearly there's something going on with the 12,000 entities in the timings report.

I'm a little bit confused by the large number of inactive chunks. I'm aware that 1.14 has changed how chunks work. Does that look right to you?

And finally, some interesting stuff in /paper debug chunks:

$ grep queued-for-unload chunks-2019-09-27_04.12.36.txt | grep false | wc -l
30186
$ grep queued-for-unload chunks-2019-09-27_04.12.36.txt | grep true | wc -l
0
$ grep INACCESSIBLE chunks-2019-09-27_04.12.36.txt | wc -l
27510
$ grep status chunks-2019-09-27_04.12.36.txt | sort | uniq -c
      7      "status": "minecraft:empty",
   1715      "status": "minecraft:features",
   9004      "status": "minecraft:full",
   1301      "status": "minecraft:liquid_carvers",
   4277      "status": "minecraft:structure_starts",
  13882      "status": "unloaded",

Those numbers are more than I expected, but I don't really know for certain what to expect in 1.14. Does that look right to you @electronicboy?

froobynooby commented 5 years ago

I think this issue may be with how the timings data is interpreted in the viewer rather than a problem in the data itself. If you choose any time window on the timings viewer, any entity under the expanded entityTick section will show 6000 ticks fewer than it should.

For example, I made a world with just me in it, made a 20 minute timings report and selected a time window of 12000 ticks:

no1

You can see that only 6000 ticks of nms.EntityPlayer are accounted for here.

The exception to this is if you choose a 6000 tick window by moving both ends of the selectors on the lag graph to the same node, like this:

no2

Now it correctly shows 6000 for both entityTick and nms.EntityPlayer

I think it's related to this issue because if you choose a 6000 tick window on any of the timings reports provided in the other comments, the problematic entities disappear, and things start looking normal again.

TheMattVid commented 4 years ago

Can confirm that this still exists for me in 2020.

https://timings.aikar.co/?id=2b510cf91ad54d6eba0a349ec3d6d3c9#timings

Depending on what period of time you select, it will list there being 500 squids, witches, zombie villagers, or horses. The number actually remains fairly consistent, but the mob attributed with it changes. This makes it impossible to diagnose the cause of my entity lag.

ArtNRG commented 4 years ago

I wrote about odd timing reports about a year ago (29 march 2019) https://i.imgur.com/IQ7vR81.png So we may search the builds somewhere near that in my opinion. We can start from this build (latest build from 29 march 2019) and try older builds: https://papermc.io/ci/job/Paper-1.13/597/changes

Is anyone know how to reproduce the issue? I can test the builds but I must know what exactly I need to do.

TNTUP commented 4 years ago

I can confirm this, sometimes high entity tick on a Zombie, next day it was Paintings, next day Bees, next day Skeletons... IMG now its on Slimes. No issues at all, just giving my two cents on this issue. TPS are fine on my side (its 1am here in Canada)

aikar commented 4 years ago

this should of been fixed.

Drc-DEV commented 3 years ago

Still happens in 1.16.4 with bees for me.

aikar commented 3 years ago

going to need some evidence/proof of that, as this was fixed and we've seen no signs of this occurring anymore since the fixes. Plus, the issue was actually on the reader side.....

DemonHunter759 commented 3 years ago

Capture still the same with paper 393 and mc 1.16.4

aikar commented 3 years ago

@DemonHunter759 that picture shows nothing to say "this is still an issue"

I checked your timings, I see no reason to believe this is a sign of that bug.

SamuelScheit commented 3 years ago

I have the same problem. I'm using PaperMC 1.16.4-521 Plugins: CoreProtect, EntityDetection, Essentials, InstantNetherPortals, LuckPerms, ServerRestorer, Shopkeepers, Sleep Entities:

Total Ticking: 940, Total Non-Ticking: 305
  126 (20) : minecraft:item
  47 (55) : minecraft:cat
  88 (0) : minecraft:item_frame
  86 (0) : minecraft:cod
  78 (7) : minecraft:villager
  80 (1) : minecraft:creeper
  68 (0) : minecraft:bat
  13 (55) : minecraft:chicken
  40 (19) : minecraft:sheep
  58 (1) : minecraft:zombie
  49 (0) : minecraft:skeleton
  39 (0) : minecraft:squid
  2 (29) : minecraft:pig
  27 (0) : minecraft:dolphin
  15 (11) : minecraft:turtle
  18 (7) : minecraft:cow
  9 (16) : minecraft:enderman
  24 (0) : minecraft:hopper_minecart
  0 (19) : minecraft:chest_minecart
  18 (0) : minecraft:spider

Timings report: https://timings.aikar.co/?id=baa10c9c71eb4d6ca07b1c45a9936b93

For me its:

Minecraft::tickEntity - villager - tickcount(362646)  total(8.83% 93.977s, 11.52% of tick)avg(0.26ms per - 5.76ms/22.23 per tick)
Minecraft::tickEntity - zombie - tickcount(546253)  total(4.83% 51.379s, 6.30% of tick)avg(0.09ms per - 3.15ms/33.48 per tick)
Minecraft::tickEntity - cod - tickcount(816180)  total(3.31% 35.204s, 4.32% of tick)avg(0.04ms per - 2.16ms/50.02 per tick)
electronicboy commented 3 years ago

that looks fine, timings only reports ticking entities, as well as aspects like averaging, etc, that looks perfectly fine, if you're reading the 362k value, you're reading the wrong number, watch the video in the top corner