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

[Feature] Add Option to deactivate the PlayerUpdateTask #1325

Closed
MWFIAE opened this Issue Oct 8, 2017 · 13 comments

Comments

Projects
None yet
4 participants
@MWFIAE

MWFIAE commented Oct 8, 2017

As mentioned in a few issues the playerupdatetask seems to cause lag.
We also encountered this problem on our server with ~100 Npc's and no patroling etc. going on.
Therefore I made a custom version of citizens without the playerupdate task. As our NPC's are just standing there and wait to be clicked it didn't seem to make much of a difference, but improved our performance hugely.
Since more users are reporting problems it would surely be nice to have just a config option to disable it if needed.

Also what features aren't working without the task? I didn't have time to test it out fully...

@mcmonkey4eva

This comment has been minimized.

Show comment
Hide comment
@mcmonkey4eva

mcmonkey4eva Oct 8, 2017

Member

Can you get an accurate profiler report from PlayerUpdateTask causing lag with no NPC's moving or anything else?

Member

mcmonkey4eva commented Oct 8, 2017

Can you get an accurate profiler report from PlayerUpdateTask causing lag with no NPC's moving or anything else?

@MWFIAE

This comment has been minimized.

Show comment
Hide comment
@MWFIAE

MWFIAE Oct 8, 2017

With accurate you mean something like a warmroast?
Unfortunatly I only have/had timings with paper. But these don't show exactly where the problem lies and instead just showed PlayerUpdateTask as cause.

Maybe I can organize a warmroast next week, but I can't promise it, as I never used it before and it seems at least somewhat complicated to make it run.

(PS: I do understand that the task is just calling some default minecraft code and is not really at fault, but it would be nonetheless nice to be able to disable it if the features needing it aren't even used. )

MWFIAE commented Oct 8, 2017

With accurate you mean something like a warmroast?
Unfortunatly I only have/had timings with paper. But these don't show exactly where the problem lies and instead just showed PlayerUpdateTask as cause.

Maybe I can organize a warmroast next week, but I can't promise it, as I never used it before and it seems at least somewhat complicated to make it run.

(PS: I do understand that the task is just calling some default minecraft code and is not really at fault, but it would be nonetheless nice to be able to disable it if the features needing it aren't even used. )

@mcmonkey4eva

This comment has been minimized.

Show comment
Hide comment
@mcmonkey4eva

mcmonkey4eva Oct 8, 2017

Member

The thing is, if nothing is using it, it shouldn't have any noticeable weight...

If it does cause lag somehow, something has gone wrong, and we need to fix that.

--

Warmroast is one option, or something like https://www.spigotmc.org/resources/lagmonitor.21348/ would work too.

Member

mcmonkey4eva commented Oct 8, 2017

The thing is, if nothing is using it, it shouldn't have any noticeable weight...

If it does cause lag somehow, something has gone wrong, and we need to fix that.

--

Warmroast is one option, or something like https://www.spigotmc.org/resources/lagmonitor.21348/ would work too.

@MWFIAE

This comment has been minimized.

Show comment
Hide comment
@MWFIAE

MWFIAE Oct 8, 2017

Ok there you go.
At the moment it doesn't look as bad as before. I will try again later.

image

[15:20:20 INFO]: [-] net.citizensnpcs.util.PlayerUpdateTask.run32.35842%
[15:20:20 INFO]: [-] net.citizensnpcs.util.NMS.tick132.0%
[15:20:20 INFO]: [-] net.citizensnpcs.nms.v1_12_R1.util.NMSImpl.tick132.0%
[15:20:20 INFO]: [-] NMS.v1_12_R1.World.entityJoinedWorld132.0%
[15:20:20 INFO]: [-] net.citizensnpcs.nms.v1_12_R1.entity.EntityHumanNPC.B_132.0%
[15:20:20 INFO]: [-] net.citizensnpcs.npc.CitizensNPC.update132.0%
[15:20:20 INFO]: [-] OBC.v1_12_R1.scoreboard.CraftTeam.setOption132.0%
[15:20:20 INFO]: [-] NMS.v1_12_R1.ScoreboardTeam.setNameTagVisibility132.0%
[15:20:20 INFO]: [-] NMS.v1_12_R1.ScoreboardServer.handleTeamChanged132.0%
[15:20:20 INFO]: [-] NMS.v1_12_R1.ScoreboardServer.sendAll132.0%
[15:20:20 INFO]: [-] NMS.v1_12_R1.PlayerConnection.sendPacket132.0%
[15:20:20 INFO]: [-] NMS.v1_12_R1.NetworkManager.sendPacket132.0%
[15:20:20 INFO]: [-] NMS.v1_12_R1.NetworkManager.a132.0%
[15:20:20 INFO]: [-] com.comphenix.protocol.injector.netty.EventLoopProxy.execute132.0%
[15:20:39 INFO]: [-] com.comphenix.protocol.injector.netty.ChannelProxy$2.schedulingRunnable132.0%
[15:20:39 INFO]: [-] com.comphenix.protocol.injector.netty.ChannelInjector$5.onMessageScheduled132.0%
[15:20:39 INFO]: [-] com.comphenix.protocol.injector.netty.ChannelInjector$5.handleScheduled132.0%
[15:20:39 INFO]: [-] com.comphenix.protocol.injector.netty.ChannelInjector.access$500132.0%
[15:20:39 INFO]: [-] com.comphenix.protocol.injector.netty.ChannelInjector.processSending132.0%
[15:20:39 INFO]: [-] com.comphenix.protocol.injector.netty.ChannelInjector.getMarker132.0%
[15:20:39 INFO]: [-] com.google.common.collect.MapMakerInternalMap.get132.0%
[15:20:39 INFO]: [-] com.google.common.collect.MapMakerInternalMap.hash132.0%
[15:20:39 INFO]: [-] com.google.common.base.Equivalence.hash132.0%
[15:20:39 INFO]: [-] com.google.common.base.Equivalence$Identity.doHash132.0%
[15:20:39 INFO]: [-] java.lang.System.identityHashCode132.0%

MWFIAE commented Oct 8, 2017

Ok there you go.
At the moment it doesn't look as bad as before. I will try again later.

image

[15:20:20 INFO]: [-] net.citizensnpcs.util.PlayerUpdateTask.run32.35842%
[15:20:20 INFO]: [-] net.citizensnpcs.util.NMS.tick132.0%
[15:20:20 INFO]: [-] net.citizensnpcs.nms.v1_12_R1.util.NMSImpl.tick132.0%
[15:20:20 INFO]: [-] NMS.v1_12_R1.World.entityJoinedWorld132.0%
[15:20:20 INFO]: [-] net.citizensnpcs.nms.v1_12_R1.entity.EntityHumanNPC.B_132.0%
[15:20:20 INFO]: [-] net.citizensnpcs.npc.CitizensNPC.update132.0%
[15:20:20 INFO]: [-] OBC.v1_12_R1.scoreboard.CraftTeam.setOption132.0%
[15:20:20 INFO]: [-] NMS.v1_12_R1.ScoreboardTeam.setNameTagVisibility132.0%
[15:20:20 INFO]: [-] NMS.v1_12_R1.ScoreboardServer.handleTeamChanged132.0%
[15:20:20 INFO]: [-] NMS.v1_12_R1.ScoreboardServer.sendAll132.0%
[15:20:20 INFO]: [-] NMS.v1_12_R1.PlayerConnection.sendPacket132.0%
[15:20:20 INFO]: [-] NMS.v1_12_R1.NetworkManager.sendPacket132.0%
[15:20:20 INFO]: [-] NMS.v1_12_R1.NetworkManager.a132.0%
[15:20:20 INFO]: [-] com.comphenix.protocol.injector.netty.EventLoopProxy.execute132.0%
[15:20:39 INFO]: [-] com.comphenix.protocol.injector.netty.ChannelProxy$2.schedulingRunnable132.0%
[15:20:39 INFO]: [-] com.comphenix.protocol.injector.netty.ChannelInjector$5.onMessageScheduled132.0%
[15:20:39 INFO]: [-] com.comphenix.protocol.injector.netty.ChannelInjector$5.handleScheduled132.0%
[15:20:39 INFO]: [-] com.comphenix.protocol.injector.netty.ChannelInjector.access$500132.0%
[15:20:39 INFO]: [-] com.comphenix.protocol.injector.netty.ChannelInjector.processSending132.0%
[15:20:39 INFO]: [-] com.comphenix.protocol.injector.netty.ChannelInjector.getMarker132.0%
[15:20:39 INFO]: [-] com.google.common.collect.MapMakerInternalMap.get132.0%
[15:20:39 INFO]: [-] com.google.common.collect.MapMakerInternalMap.hash132.0%
[15:20:39 INFO]: [-] com.google.common.base.Equivalence.hash132.0%
[15:20:39 INFO]: [-] com.google.common.base.Equivalence$Identity.doHash132.0%
[15:20:39 INFO]: [-] java.lang.System.identityHashCode132.0%

@mcmonkey4eva

This comment has been minimized.

Show comment
Hide comment
@mcmonkey4eva

mcmonkey4eva Oct 8, 2017

Member

Appears to be scoreboard teams malfunctioning 0.o
Could try disabling that feature in particular maybe? (Scoreboard teams) (via the config file)

Member

mcmonkey4eva commented Oct 8, 2017

Appears to be scoreboard teams malfunctioning 0.o
Could try disabling that feature in particular maybe? (Scoreboard teams) (via the config file)

@mcmonkey4eva

This comment has been minimized.

Show comment
Hide comment
@mcmonkey4eva

mcmonkey4eva Oct 8, 2017

Member

Or changing the packet update delay option.

Member

mcmonkey4eva commented Oct 8, 2017

Or changing the packet update delay option.

@MWFIAE

This comment has been minimized.

Show comment
Hide comment
@MWFIAE

MWFIAE Oct 8, 2017

Ok, with scoreboard-teams disabled it looks like this:
(I have no clue what it does, btw)

image

[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.MinecraftServer.C32.5988%
[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.DedicatedServer.D132.0%
[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.MinecraftServer.D132.0%
[15:32:58] [Server thread/INFO]: [-] OBC.v1_12_R1.scheduler.CraftScheduler.mainThreadHeartbeat57.0%
[15:32:58] [Server thread/INFO]: [-] OBC.v1_12_R1.scheduler.CraftTask.run132.0%
[15:32:58] [Server thread/INFO]: [-] net.citizensnpcs.util.PlayerUpdateTask.run132.0%
[15:32:58] [Server thread/INFO]: [-] net.citizensnpcs.util.NMS.tick132.0%
[15:32:58] [Server thread/INFO]: [-] net.citizensnpcs.nms.v1_12_R1.util.NMSImpl.tick132.0%
[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.World.entityJoinedWorld132.0%
[15:32:58] [Server thread/INFO]: [-] net.citizensnpcs.nms.v1_12_R1.entity.EntityHumanNPC.B_132.0%
[15:32:58] [Server thread/INFO]: [-] net.citizensnpcs.nms.v1_12_R1.entity.EntityHumanNPC.a132.0%
[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.EntityHuman.a132.0%
[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.EntityLiving.a132.0%
[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.Entity.move132.0%
[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.World.getCubes132.0%
[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.World.a132.0%
[15:32:58] [Server thread/INFO]: ... 529 more entries. Click the arrows above or type /lagpage next
[15:33:02] [Server thread/INFO]: Monitor from Oct 8, 2017 3:31:26 PM << 10 / 23 >>
[15:33:02] [Server thread/INFO]: [-] NMS.v1_12_R1.BlockStateList$BlockData.a132.0%
[15:33:02] [Server thread/INFO]: [-] NMS.v1_12_R1.BlockStairs.a132.0%
[15:33:02] [Server thread/INFO]: [-] NMS.v1_12_R1.BlockStairs.updateState132.0%
[15:33:02] [Server thread/INFO]: [-] NMS.v1_12_R1.BlockStateList$BlockData.set132.0%
[15:33:02] [Server thread/INFO]: [-] com.google.common.collect.ImmutableTable.get132.0%
[15:33:02] [Server thread/INFO]: [-] com.google.common.collect.AbstractTable.get132.0%
[15:33:02] [Server thread/INFO]: [-] com.google.common.collect.Maps.safeGet132.0%
[15:33:02] [Server thread/INFO]: [-] com.google.common.collect.RegularImmutableMap.get132.0%
[15:33:02] [Server thread/INFO]: [-] com.google.common.collect.RegularImmutableMap.get132.0%

To what should I change the packet update delay? Right now it's 30.
Should scoreboard teams be enabled for this test?

MWFIAE commented Oct 8, 2017

Ok, with scoreboard-teams disabled it looks like this:
(I have no clue what it does, btw)

image

[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.MinecraftServer.C32.5988%
[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.DedicatedServer.D132.0%
[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.MinecraftServer.D132.0%
[15:32:58] [Server thread/INFO]: [-] OBC.v1_12_R1.scheduler.CraftScheduler.mainThreadHeartbeat57.0%
[15:32:58] [Server thread/INFO]: [-] OBC.v1_12_R1.scheduler.CraftTask.run132.0%
[15:32:58] [Server thread/INFO]: [-] net.citizensnpcs.util.PlayerUpdateTask.run132.0%
[15:32:58] [Server thread/INFO]: [-] net.citizensnpcs.util.NMS.tick132.0%
[15:32:58] [Server thread/INFO]: [-] net.citizensnpcs.nms.v1_12_R1.util.NMSImpl.tick132.0%
[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.World.entityJoinedWorld132.0%
[15:32:58] [Server thread/INFO]: [-] net.citizensnpcs.nms.v1_12_R1.entity.EntityHumanNPC.B_132.0%
[15:32:58] [Server thread/INFO]: [-] net.citizensnpcs.nms.v1_12_R1.entity.EntityHumanNPC.a132.0%
[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.EntityHuman.a132.0%
[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.EntityLiving.a132.0%
[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.Entity.move132.0%
[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.World.getCubes132.0%
[15:32:58] [Server thread/INFO]: [-] NMS.v1_12_R1.World.a132.0%
[15:32:58] [Server thread/INFO]: ... 529 more entries. Click the arrows above or type /lagpage next
[15:33:02] [Server thread/INFO]: Monitor from Oct 8, 2017 3:31:26 PM << 10 / 23 >>
[15:33:02] [Server thread/INFO]: [-] NMS.v1_12_R1.BlockStateList$BlockData.a132.0%
[15:33:02] [Server thread/INFO]: [-] NMS.v1_12_R1.BlockStairs.a132.0%
[15:33:02] [Server thread/INFO]: [-] NMS.v1_12_R1.BlockStairs.updateState132.0%
[15:33:02] [Server thread/INFO]: [-] NMS.v1_12_R1.BlockStateList$BlockData.set132.0%
[15:33:02] [Server thread/INFO]: [-] com.google.common.collect.ImmutableTable.get132.0%
[15:33:02] [Server thread/INFO]: [-] com.google.common.collect.AbstractTable.get132.0%
[15:33:02] [Server thread/INFO]: [-] com.google.common.collect.Maps.safeGet132.0%
[15:33:02] [Server thread/INFO]: [-] com.google.common.collect.RegularImmutableMap.get132.0%
[15:33:02] [Server thread/INFO]: [-] com.google.common.collect.RegularImmutableMap.get132.0%

To what should I change the packet update delay? Right now it's 30.
Should scoreboard teams be enabled for this test?

@fullwall

This comment has been minimized.

Show comment
Hide comment
@fullwall

fullwall Oct 18, 2017

Member

If you disable removefromplayerlist the PlayerUpdateTask will not be used. In these cases we often find that Minecraft's internal logic is causing the slowdown, it just appears to be coming from Citizens. The packet update delay is in ticks. Is this screenshot from WarmRoast? Having everything be 132% is quite unusual, and points to some concurrency double-counting and/or profiling issues if so.

Member

fullwall commented Oct 18, 2017

If you disable removefromplayerlist the PlayerUpdateTask will not be used. In these cases we often find that Minecraft's internal logic is causing the slowdown, it just appears to be coming from Citizens. The packet update delay is in ticks. Is this screenshot from WarmRoast? Having everything be 132% is quite unusual, and points to some concurrency double-counting and/or profiling issues if so.

@MWFIAE

This comment has been minimized.

Show comment
Hide comment
@MWFIAE

MWFIAE Oct 18, 2017

The screens/logs are from lagmonitor.

MWFIAE commented Oct 18, 2017

The screens/logs are from lagmonitor.

@fullwall

This comment has been minimized.

Show comment
Hide comment
@fullwall

fullwall Oct 18, 2017

Member

Can you please try and get a WarmRoast profile?

Member

fullwall commented Oct 18, 2017

Can you please try and get a WarmRoast profile?

@MWFIAE

This comment has been minimized.

Show comment
Hide comment
@MWFIAE

MWFIAE Oct 18, 2017

I tried to, but it doesn't work for me.


WarmRoast
http://github.com/sk89q/warmroast

Choose a VM:
[1] PaperSpigot-1.12.1-b1204.jar nogui

Enter choice #: 1

Failed to attach VM
java.io.IOException: well-known file is not secure
at sun.tools.attach.LinuxVirtualMachine.checkPermissions(Native Method)
at sun.tools.attach.LinuxVirtualMachine.(LinuxVirtualMachine.java:117)
at sun.tools.attach.LinuxAttachProvider.attachVirtualMachine(LinuxAttachProvider.java:78)
at com.sun.tools.attach.VirtualMachine.attach(VirtualMachine.java:250)
at com.sk89q.warmroast.WarmRoast.main(WarmRoast.java:282)

MWFIAE commented Oct 18, 2017

I tried to, but it doesn't work for me.


WarmRoast
http://github.com/sk89q/warmroast

Choose a VM:
[1] PaperSpigot-1.12.1-b1204.jar nogui

Enter choice #: 1

Failed to attach VM
java.io.IOException: well-known file is not secure
at sun.tools.attach.LinuxVirtualMachine.checkPermissions(Native Method)
at sun.tools.attach.LinuxVirtualMachine.(LinuxVirtualMachine.java:117)
at sun.tools.attach.LinuxAttachProvider.attachVirtualMachine(LinuxAttachProvider.java:78)
at com.sun.tools.attach.VirtualMachine.attach(VirtualMachine.java:250)
at com.sk89q.warmroast.WarmRoast.main(WarmRoast.java:282)

@Cryptite

This comment has been minimized.

Show comment
Hide comment
@Cryptite

Cryptite Dec 5, 2017

I too am curious what the use of the task is as it's been causing notable TPS loss for us as well. It does seem to be either some NPC or set of NPCs or something that causes it because we have consistent player counts, but the TPS loss is variable, as though loading the chunks is activating some bad NPC or something strange.

Here's a profile breakdown of it for my server:
image

And timings of the same:
image

It's a chief issue for us at times too.

Cryptite commented Dec 5, 2017

I too am curious what the use of the task is as it's been causing notable TPS loss for us as well. It does seem to be either some NPC or set of NPCs or something that causes it because we have consistent player counts, but the TPS loss is variable, as though loading the chunks is activating some bad NPC or something strange.

Here's a profile breakdown of it for my server:
image

And timings of the same:
image

It's a chief issue for us at times too.

@fullwall

This comment has been minimized.

Show comment
Hide comment
@fullwall

fullwall Mar 9, 2018

Member

@Cryptite is rabbitMQ not eating up 16% of the server tick there?

Member

fullwall commented Mar 9, 2018

@Cryptite is rabbitMQ not eating up 16% of the server tick there?

@fullwall fullwall closed this Mar 15, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment