Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
totemo opened this issue Aug 22, 2019 · 3 comments

Comments

@totemo
Copy link

commented Aug 22, 2019

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. 😄

@galacticwarrior9

This comment has been minimized.

Copy link

commented Aug 22, 2019

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

This comment has been minimized.

Copy link

commented Aug 22, 2019

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

This comment has been minimized.

Copy link
Author

commented Aug 24, 2019

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) [?:?]
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
3 participants
You can’t perform that action at this time.