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

PlayerUpdateTask high CPU usage #1339

Closed
lucko opened this Issue Oct 29, 2017 · 13 comments

Comments

Projects
None yet
4 participants
@lucko

lucko commented Oct 29, 2017

Hi. Over the last few weeks, I've noticed consistently high timings for the PlayerUpdateTask.

We have a lot of pathfinding NPCs on our server, so I initially dismissed it as perhaps being reasonable. However, on closer inspection, it seems the part of the task which is consuming tick time isn't pathfinding.

Timings reports:
Citizens::Task: net.citizensnpcs.util.PlayerUpdateTask (interval:1)count(15496) total(11.44% 103.448s, 13.19% of tick)

With approx 100 players online, that task is occupying around 13% of the tick.

However, profiling shows that the biggest CPU drain in the entity tick is clearing advancement progress.

This behaviour was added by 0a6b954, has it since been preceded by 7899252? In other words is it still necessary?

I'm going to trial moving this

https://github.com/CitizensDev/Citizens2/blob/master/v1_12_R1/src/main/java/net/citizensnpcs/nms/v1_12_R1/entity/EntityHumanNPC.java#L125-L129

to here

https://github.com/CitizensDev/Citizens2/blob/master/v1_12_R1/src/main/java/net/citizensnpcs/nms/v1_12_R1/entity/EntityHumanNPC.java#L201

on the assumption that it doesn't really need to be executed every time the NPC is ticked? Perhaps that's a bad assumption..? I don't know.

I felt I should at least make you aware of this, in case there's a more obvious fix you know of. :)

lucko added a commit to lucko/Citizens2 that referenced this issue Oct 29, 2017

@Cryptite

This comment has been minimized.

Show comment
Hide comment
@Cryptite

Cryptite Dec 5, 2017

We're having the issue differently ourselves. I've posted some profiling data in the other major issue about this: #1325 (comment)

Cryptite commented Dec 5, 2017

We're having the issue differently ourselves. I've posted some profiling data in the other major issue about this: #1325 (comment)

@fullwall

This comment has been minimized.

Show comment
Hide comment
@fullwall

fullwall Mar 9, 2018

Member

Try the latest build, it should be faster

Member

fullwall commented Mar 9, 2018

Try the latest build, it should be faster

@Cryptite

This comment has been minimized.

Show comment
Hide comment
@Cryptite

Cryptite Mar 10, 2018

This still eats up a pretty significant chunk of the server tick.
image

Here're full timings: https://timings.aikar.co/?id=2033ae61c6e041909b8bf66a4e5405b5

Cryptite commented Mar 10, 2018

This still eats up a pretty significant chunk of the server tick.
image

Here're full timings: https://timings.aikar.co/?id=2033ae61c6e041909b8bf66a4e5405b5

@fullwall

This comment has been minimized.

Show comment
Hide comment
@fullwall

fullwall Mar 11, 2018

Member

Players are expensive to run, I'd need output from a better profiler to pin down the problem. Aikar's timings are not helpful in 99% of cases.

Member

fullwall commented Mar 11, 2018

Players are expensive to run, I'd need output from a better profiler to pin down the problem. Aikar's timings are not helpful in 99% of cases.

@Cryptite

This comment has been minimized.

Show comment
Hide comment
@Cryptite

Cryptite Mar 14, 2018

Seems to be the ticking. Here're another set of screencaps from YourKit and Timings:

image

image

Cryptite commented Mar 14, 2018

Seems to be the ticking. Here're another set of screencaps from YourKit and Timings:

image

image

@mcmonkey4eva

This comment has been minimized.

Show comment
Hide comment
@mcmonkey4eva

mcmonkey4eva Mar 14, 2018

Member

That's largely just standard player/entity tick there according to the YourKit timings.

It's also... not in the slightest bit significant compared to overall timings. 0% of the full thread time, and about 2% of the main server tick.

Member

mcmonkey4eva commented Mar 14, 2018

That's largely just standard player/entity tick there according to the YourKit timings.

It's also... not in the slightest bit significant compared to overall timings. 0% of the full thread time, and about 2% of the main server tick.

@Cryptite

This comment has been minimized.

Show comment
Hide comment
@Cryptite

Cryptite Mar 14, 2018

Indeed it's not causing my server strain at the moment, but it's not an insignificant portion of the server tick. I do have a large player-count fight coming soonish and might be able to report back if it causes problems relative to player count.

Cryptite commented Mar 14, 2018

Indeed it's not causing my server strain at the moment, but it's not an insignificant portion of the server tick. I do have a large player-count fight coming soonish and might be able to report back if it causes problems relative to player count.

@fullwall

This comment has been minimized.

Show comment
Hide comment
@fullwall

fullwall Mar 15, 2018

Member

I'd trust YourKit's sampling over the timings plugin sampling, although I'm not sure you have the right settings there as it's all being rounded down to 0. I use jProfiler myself and it has an option to report average time spent in function which would be more helpful if there is the same thing in YourKit.

Member

fullwall commented Mar 15, 2018

I'd trust YourKit's sampling over the timings plugin sampling, although I'm not sure you have the right settings there as it's all being rounded down to 0. I use jProfiler myself and it has an option to report average time spent in function which would be more helpful if there is the same thing in YourKit.

@Cryptite

This comment has been minimized.

Show comment
Hide comment
@Cryptite

Cryptite Mar 15, 2018

Here's a different view:

image

Time(ms) is "Time spent in the method including time spent in subcalls.
Own Time (ms) is "Time spent in the method excluding time spent in subcalls"

Given the nature of how we use our NPCs, is there a "dumb mode" or set of commands we can utilize to reduce the number of checks done on NPCs? Our NPCs never move, never take damage, are only ever used for basic right-clicking and we have lookclose on for most of them. It seems a lot of work is being done to make these NPCs be a "normal player" in terms of the types of ticking checks going on.

Cryptite commented Mar 15, 2018

Here's a different view:

image

Time(ms) is "Time spent in the method including time spent in subcalls.
Own Time (ms) is "Time spent in the method excluding time spent in subcalls"

Given the nature of how we use our NPCs, is there a "dumb mode" or set of commands we can utilize to reduce the number of checks done on NPCs? Our NPCs never move, never take damage, are only ever used for basic right-clicking and we have lookclose on for most of them. It seems a lot of work is being done to make these NPCs be a "normal player" in terms of the types of ticking checks going on.

@fullwall

This comment has been minimized.

Show comment
Hide comment
@fullwall

fullwall Mar 15, 2018

Member

Eh, again this isn't really helpful because it's not an average, just a total. Even this view shows that 100/33,564 = 0.3% of time total was spent in EntityHumanNPC#B_() which seems really miniscule compared to the rest of the subcalls. Why do you think Citizens is the problem here?

Member

fullwall commented Mar 15, 2018

Eh, again this isn't really helpful because it's not an average, just a total. Even this view shows that 100/33,564 = 0.3% of time total was spent in EntityHumanNPC#B_() which seems really miniscule compared to the rest of the subcalls. Why do you think Citizens is the problem here?

@Cryptite

This comment has been minimized.

Show comment
Hide comment
@Cryptite

Cryptite Mar 15, 2018

Mostly just digging into whether it's causing much of a performance hit and it's eating up too much CPU than it needs to be.

Cryptite commented Mar 15, 2018

Mostly just digging into whether it's causing much of a performance hit and it's eating up too much CPU than it needs to be.

@lucko

This comment has been minimized.

Show comment
Hide comment
@lucko

lucko Mar 15, 2018

Hi, thanks for responding & working on this fullwall <3

The patch I linked in the original post fixed the issue for me - I had a quick look at your latest commit and it looks like it will have the same effect. As far as I'm concerned this can be closed now. :)

lucko commented Mar 15, 2018

Hi, thanks for responding & working on this fullwall <3

The patch I linked in the original post fixed the issue for me - I had a quick look at your latest commit and it looks like it will have the same effect. As far as I'm concerned this can be closed now. :)

@mcmonkey4eva

This comment has been minimized.

Show comment
Hide comment
@mcmonkey4eva

mcmonkey4eva Mar 15, 2018

Member

Woo! :D

Member

mcmonkey4eva commented Mar 15, 2018

Woo! :D

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