mojira.dev
MC-146579

Server CPU usage at 100% for all cores

Resolved
Duplicate
0

Server has CPU usage to 100% causes many tick delays listed in debug mode. Starts to happen after players join and continues to do so after all players leave server. CPU usage jumps to 100% on all cores for about 5-10 seconds (maybe more) and repeats often, causing server lag, such as moving too quickly, not being able to pick up items, or opening chests. CPU usage on all cores is always >50% with players on. 

Update: Caused server to crash

19w12b\: [^crash-2019-03-23_21.03.46-server.txt]

---- Minecraft Crash Report ----
// I'm sorry, Dave.

Time: 3/23/19 9:03 PM
Description: Watching Server

java.lang.Error
	at uw.a(SourceFile:162)
	at uw.a(SourceFile:182)
	at vb.c(SourceFile:132)
	at vb.b(SourceFile:113)
	at vb.a(SourceFile:100)
	at bgf.a(SourceFile:195)
	at bgi.a(SourceFile:98)
	at bgf.c(SourceFile:190)
	at bgf.e_(SourceFile:411)
	at cme.a(SourceFile:420)
	at cme.a(SourceFile:408)
	at cme.a(SourceFile:327)
	at cme.a(SourceFile:292)
	at aoi.a(SourceFile:205)
	at aoi.a(SourceFile:131)
	at aoj.m(SourceFile:241)
	at aoj.c(SourceFile:195)
	at aii.cX(SourceFile:619)
	at aih.k(SourceFile:2206)
	at aii.k(SourceFile:479)
	at ahw.k(SourceFile:141)
	at apr.k(SourceFile:46)
	at aqj.k(SourceFile:132)
	at aih.h(SourceFile:2051)
	at aii.h(SourceFile:293)
	at vd.a(SourceFile:581)
	at vd$$Lambda$2308/768278870.accept(Unknown Source)
	at bgf.a(SourceFile:668)
	at vd.a(SourceFile:384)
	at net.minecraft.server.MinecraftServer.b(SourceFile:816)
	at ue.b(SourceFile:343)
	at net.minecraft.server.MinecraftServer.a(SourceFile:755)
	at net.minecraft.server.MinecraftServer.run(SourceFile:630)
	at java.lang.Thread.run(Thread.java:748)


A detailed walkthrough of the error, its code path and all known details is as follows:
---------------------------------------------------------------------------------------

-- Head --
Thread: Server Watchdog
Stacktrace:
	at uw.a(SourceFile:162)
	at uw.a(SourceFile:182)
	at vb.c(SourceFile:132)
	at vb.b(SourceFile:113)
	at vb.a(SourceFile:100)
	at bgf.a(SourceFile:195)
	at bgi.a(SourceFile:98)
	at bgf.c(SourceFile:190)
	at bgf.e_(SourceFile:411)
	at cme.a(SourceFile:420)
	at cme.a(SourceFile:408)
	at cme.a(SourceFile:327)
	at cme.a(SourceFile:292)
	at aoi.a(SourceFile:205)
	at aoi.a(SourceFile:131)
	at aoj.m(SourceFile:241)
	at aoj.c(SourceFile:195)
	at aii.cX(SourceFile:619)
	at aih.k(SourceFile:2206)
	at aii.k(SourceFile:479)
	at ahw.k(SourceFile:141)
	at apr.k(SourceFile:46)
	at aqj.k(SourceFile:132)
	at aih.h(SourceFile:2051)
	at aii.h(SourceFile:293)
	at vd.a(SourceFile:581)
	at vd$$Lambda$2308/768278870.accept(Unknown Source)
	at bgf.a(SourceFile:668)
	at vd.a(SourceFile:384)
	at net.minecraft.server.MinecraftServer.b(SourceFile:816)
	at ue.b(SourceFile:343)
	at net.minecraft.server.MinecraftServer.a(SourceFile:755)

-- Thread Dump --
Details:
	Threads: "Server-Worker-1954" Id=2049 TIMED_WAITING on java.util.concurrent.ForkJoinPool@6db177da
	at sun.misc.Unsafe.park(Native Method)
	-  waiting on java.util.concurrent.ForkJoinPool@6db177da
	at java.util.concurrent.ForkJoinPool.awaitWork(ForkJoinPool.java:1824)
	at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1693)
	at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)


"Server-Worker-1951" Id=2046 WAITING on java.util.concurrent.ForkJoinPool@6db177da
	at sun.misc.Unsafe.park(Native Method)
	-  waiting on java.util.concurrent.ForkJoinPool@6db177da
	at java.util.concurrent.ForkJoinPool.awaitWork(ForkJoinPool.java:1824)
	at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1693)
	at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)


"Netty Epoll Server IO #7" Id=501 RUNNABLE (in native)
	at io.netty.channel.epoll.Native.epollWait0(Native Method)
	at io.netty.channel.epoll.Native.epollWait(Native.java:114)
	at io.netty.channel.epoll.EpollEventLoop.epollWait(EpollEventLoop.java:239)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:256)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
	at java.lang.Thread.run(Thread.java:748)


"Netty Epoll Server IO #6" Id=255 RUNNABLE (in native)
	at io.netty.channel.epoll.Native.epollWait0(Native Method)
	at io.netty.channel.epoll.Native.epollWait(Native.java:114)
	at io.netty.channel.epoll.EpollEventLoop.epollWait(EpollEventLoop.java:239)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:256)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
	at java.lang.Thread.run(Thread.java:748)


"Netty Epoll Server IO #5" Id=62 RUNNABLE (in native)
	at io.netty.channel.epoll.Native.epollWait0(Native Method)
	at io.netty.channel.epoll.Native.epollWait(Native.java:114)
	at io.netty.channel.epoll.EpollEventLoop.epollWait(EpollEventLoop.java:239)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:256)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
	at java.lang.Thread.run(Thread.java:748)


"Netty Epoll Server IO #4" Id=61 RUNNABLE (in native)
	at io.netty.channel.epoll.Native.epollWait0(Native Method)
	at io.netty.channel.epoll.Native.epollWait(Native.java:114)
	at io.netty.channel.epoll.EpollEventLoop.epollWait(EpollEventLoop.java:239)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:256)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
	at java.lang.Thread.run(Thread.java:748)


"Netty Epoll Server IO #3" Id=60 RUNNABLE
	at io.netty.channel.epoll.Native.epollWait0(Native Method)
	at io.netty.channel.epoll.Native.epollWait(Native.java:114)
	at io.netty.channel.epoll.EpollEventLoop.epollWait(EpollEventLoop.java:239)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:256)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
	at java.lang.Thread.run(Thread.java:748)


"Netty Epoll Server IO #2" Id=25 RUNNABLE (in native)
	at io.netty.channel.epoll.Native.epollWait0(Native Method)
	at io.netty.channel.epoll.Native.epollWait(Native.java:114)
	at io.netty.channel.epoll.EpollEventLoop.epollWait(EpollEventLoop.java:239)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:256)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
	at java.lang.Thread.run(Thread.java:748)


"Netty Epoll Server IO #1" Id=24 RUNNABLE
	at io.netty.channel.epoll.Native.epollWait0(Native Method)
	at io.netty.channel.epoll.Native.epollWait(Native.java:114)
	at io.netty.channel.epoll.EpollEventLoop.epollWait(EpollEventLoop.java:239)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:256)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
	at java.lang.Thread.run(Thread.java:748)


"Server Watchdog" Id=23 RUNNABLE
	at sun.management.ThreadImpl.dumpThreads0(Native Method)
	at sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:454)
	at uh.run(SourceFile:45)
	at java.lang.Thread.run(Thread.java:748)


"Netty Epoll Server IO #0" Id=22 RUNNABLE (in native)
	at io.netty.channel.epoll.Native.epollWait0(Native Method)
	at io.netty.channel.epoll.Native.epollWait(Native.java:114)
	at io.netty.channel.epoll.EpollEventLoop.epollWait(EpollEventLoop.java:239)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:256)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
	at java.lang.Thread.run(Thread.java:748)


"ObjectCleanerThread" Id=21 TIMED_WAITING on java.lang.ref.ReferenceQueue$Lock@6376941c
	at java.lang.Object.wait(Native Method)
	-  waiting on java.lang.ref.ReferenceQueue$Lock@6376941c
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
	at io.netty.util.internal.ObjectCleaner$1.run(ObjectCleaner.java:54)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.run(Thread.java:748)


"Server console handler" Id=20 RUNNABLE (in native)
	at java.io.FileInputStream.readBytes(Native Method)
	at java.io.FileInputStream.read(FileInputStream.java:255)
	at java.io.BufferedInputStream.read1(BufferedInputStream.java:284)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
	-  locked java.io.BufferedInputStream@67491caa
	at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
	at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
	at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
	-  locked java.io.InputStreamReader@224b9e27
	at java.io.InputStreamReader.read(InputStreamReader.java:184)
	...


"DestroyJavaVM" Id=19 RUNNABLE


"Server thread" Id=16 RUNNABLE
	at uw.a(SourceFile:162)
	at uw.a(SourceFile:182)
	at vb.c(SourceFile:132)
	at vb.b(SourceFile:113)
	at vb.a(SourceFile:100)
	at bgf.a(SourceFile:195)
	at bgi.a(SourceFile:98)
	at bgf.c(SourceFile:190)
	...


"Server Infinisleeper" Id=17 TIMED_WAITING
	at java.lang.Thread.sleep(Native Method)
	at ue$1.run(SourceFile:93)


"Snooper Timer" Id=15 WAITING on java.util.TaskQueue@44223213
	at java.lang.Object.wait(Native Method)
	-  waiting on java.util.TaskQueue@44223213
	at java.lang.Object.wait(Object.java:502)
	at java.util.TimerThread.mainLoop(Timer.java:526)
	at java.util.TimerThread.run(Timer.java:505)


"Signal Dispatcher" Id=4 RUNNABLE


"Finalizer" Id=3 WAITING on java.lang.ref.ReferenceQueue$Lock@132398ff
	at java.lang.Object.wait(Native Method)
	-  waiting on java.lang.ref.ReferenceQueue$Lock@132398ff
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)


"Reference Handler" Id=2 WAITING on java.lang.ref.Reference$Lock@3ca06a7d
	at java.lang.Object.wait(Native Method)
	-  waiting on java.lang.ref.Reference$Lock@3ca06a7d
	at java.lang.Object.wait(Object.java:502)
	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)



Stacktrace:
	at uh.run(SourceFile:61)
	at java.lang.Thread.run(Thread.java:748)

-- System Details --
Details:
	Minecraft Version: 19w12b
	Operating System: Linux (amd64) version 4.15.0-46-generic
	Java Version: 1.8.0_201, Oracle Corporation
	Java VM Version: Java HotSpot(TM) 64-Bit Server VM (mixed mode), Oracle Corporation
	Memory: 1125588296 bytes (1073 MB) / 6380584960 bytes (6085 MB) up to 6380584960 bytes (6085 MB)
	JVM Flags: 2 total; -Xmx6144M -Xms4096M
	Player Count: 2 / 20; [ve['Betterllcoolace'/5437050, l='world', x=12.06, y=31.00, z=-540.71], ve['Diensn'/5437891, l='world', x=-8.61, y=95.78, z=-613.42]]
	Data Packs: vanilla
	Is Modded: Unknown (can't tell)
	Type: Dedicated Server (map_server.txt)

Related issues

duplicates

is duplicated by

relates to

Attachments

2019-03-23-1.log
crash-2019-03-23_21.03.46-server.txt
 image-2019-03-23-20-52-22-877.png
profile-results-2019-05-14_20.07.27.txt
profile-results-2019-05-14_20.21.29.txt
profile-results-2019-05-14_23.14.10.txt
 SERV.png

Comments

migrated
[media][media][media][media][media][media][media]
migrated

I can confirm that this bug is still in the latest stable 1.14 release. CPU load is at 100% when no players are logged in. 

Johnibur

This issue is not obvious to reproduce. I personally have my CPU at 1.2% when no player is on. With several players, it oscillates, but rarely reaches more than 30%. Can you join the full debug profiling? Have you tried this from a new fresh world? What are your server properties?

migrated

Did you try reproducing this on a single core machine?

This may require a specific platform setup to reproduce.  I can reproduce this on a single core vm running Arch linux with open jdk 8.

migrated

If you are able to, running the built-in debug profiler and/or a dedicated profiler (like VisualVM) and attaching the results would also be very useful in order to find the cause.

migrated

I have exact same setup as Justin (single-core, Arch Linux with OpenJDK8, not VM but real hardware). And I have the same problems:

  • CPU usage 25% when no players logged on

  • CPU usage 100% when playing on the server (things goes very slowly on the server, almost unplayable)

  • When 3 users are logged on at the same time, the server crashes.

  • The problem was there in 1.14 and is still there in 1.14.1

@Jochem: Are there any instructions how to turn on the built-in debug profiler?

If you want I can attach crash reports.

migrated

You can use the /debug start and /debug stop commands, see the wiki.

migrated
[media]
migrated

@Jochem: Here are profiling results when I play on the server with one player:

[media]

Not too bad performance after a while. But using almost 100% CPU. I was not able to test with multiple players right now (the scenario when it crashes).

Is it possible to do profiling when there are no players logged in? It would be interesting to know why it is using CPU when not in use.

migrated

You can start a debug profiling session from the console or using RCON.

migrated

Allright, but I don't have any server console (nogui) and never used RCON. But maybe this is good enough:

  • I logged in as a player, started debug, and logged out

  • waited some time...

  • I logged in again as a player, and stopped debug

Here is the profiling result from that run: 

[media]
migrated

When you start the server with -nogui you can still enter commands (if the terminal is still attached). Just type the command and hit enter.

migrated

This is what I did now: I restarted the server and waited for it to completely start. I didn't log in as a player. I ran debug start/stop from the terminal and got new profiling data here: 

[media]

Between the /debug commands this was appearing in the console:

/debug start
[23:13:22] [Server thread/INFO]: Started debug profiling
[23:13:41] [Server thread/WARN]: Something's taking too long! 'root.tick.levels.world_merged_baard minecraft:overworld.tick.chunkSource.chunks.pollingChunks' took aprox 189.156585 ms
[23:13:41] [Server thread/WARN]: Something's taking too long! 'root.tick.levels.world_merged_baard minecraft:overworld.tick.chunkSource.chunks' took aprox 189.848294 ms
[23:13:41] [Server thread/WARN]: Something's taking too long! 'root.tick.levels.world_merged_baard minecraft:overworld.tick.chunkSource' took aprox 194.153756 ms
[23:13:41] [Server thread/WARN]: Something's taking too long! 'root.tick.levels.world_merged_baard minecraft:overworld.tick' took aprox 194.774353 ms
[23:13:41] [Server thread/WARN]: Something's taking too long! 'root.tick.levels.world_merged_baard minecraft:overworld' took aprox 195.017934 ms
[23:13:41] [Server thread/WARN]: Something's taking too long! 'root.tick.levels' took aprox 195.542521 ms
[23:13:41] [Server thread/WARN]: Something's taking too long! 'root.tick' took aprox 195.790319 ms
[23:13:41] [Server thread/WARN]: Something's taking too long! 'root' took aprox 195.965604 ms
/debug stop
[23:14:10] [Server thread/INFO]: Stopped debug profiling after 47.50 seconds and 951 ticks (20.02 ticks per second)

During the run, I could see one thread that was constantly using ~25% CPU.

migrated

This happened to me in 1.14.1 as well!

migrated

1.14.1 is not stable at all for server hosting. Update is not updated which results in very laggy gameplay and constant lagspikes.

migrated

My computer still sounds like Apollo 13's launch sequence and gets twice as hot when running this, even with all settings turned down. Very disappointed that I can't play, and never had these issues with 1.13. Perhaps it's because of the increase in chunk size?

Makzevu

Discussion for all reports on Mojira related to Performance Errors.

migrated

(Unassigned)

Unconfirmed

Crash, Performance

Minecraft 19w12b, Minecraft 1.14, Minecraft 1.14.1

Retrieved