MC-1508241.14 Server using 100% of CPU and RAM
I've seen other reports of this... but it is NOT resolved. So don't mark this as duplicate please, because it is very much an issue and HUGE one at that, affecting every single server I have come across playing in this version. There is so much rubber banding and server lag, because even when no one is playing, 100% of the CPU core is being used! Please fix this! It's unplayable!
Linked Issues
Created Issue:
1.14 Server using 100% of CPU and RAM
I've seen other reports of this... but it is NOT resolved. So don't mark this as duplicate please, because it is very much an issue and HUGE one at that, affecting every single server I have come across playing in this version. There is so much rubber banding and server lag, because even when no one is playing, 100% of the CPU core is being used! Please fix this! It's unplayable!
![[Mod] violine1101](../../../data/avatars/users/92858.png){kind=small}
is duplicated by
These new updates are terrible.. so many problems in community servers
![[Mod] Michael Wobst](../../../data/avatars/users/37868.png){kind=small}
is duplicated by
is duplicated by
![[Mojang] Adrian Östergård](../../../data/assets/gravatar/nighter.jpeg){kind=small}
![[Bot] Arisa](../../../data/assets/gravatar/mustek2.png){kind=small}
duplicates
relates to
![[Bot] Arisa](../../../data/avatars/users/43007.png){kind=small}
is duplicated by
relates to
![[Mod] Asteraoth](../../../data/avatars/users/92886.png){kind=small}
Happens to me all the time, even when nobody's on.
I use JDK and force MC to use all cores and it still constantly is ~1,200ms-15,000ms behind. Averages around 2,000-3,000ms when no one is logged in. Server has 6 cores and 12Gig of RAM, uses ~30% CPU with no one on. Does not scale at all.
Cannot reproduce. What JVM arguments are you using? Can you provide a debug profiling?
(wait for a few)
and join the report you'll find in debug folder.
Here my Debug, 1 core of my (8 cores / 16 threads) GOES 100% all the time.profile-results-2019-05-08_13.13.20.txt
Cristina Try disabling the server's gui with the nogui option.
Also, what are your JVM arguments?
java -jar 1.14.1pre.jar -nogui
We have stupidly high processor usage as well. We started the world in one of the snapshots (not sure which one) and have upgraded though every snapshot and pre-release since.
For what it's worth, here is a screenshot from my dedicated PC running Arch Linux with Minecraft server 1.14 (md5 of jar: 177e83e7563b08509c70b1296583f29f).
It is constantly using ~25% CPU, even when there is no player logged on.
My Java version:
Bug Duplicated? https://bugs.mojang.com/browse/MC-149018
Mine has been maxing out the RAM steadily over the course of a day. Currently, I am the only one logged on, I have not moved more than a couple chunks from my loading spot, and the RAM usage is almost 60%.
Edit: This is also affecting 1.14.1. I can restart the server to temporarily reduce the RAM used, but it restarts and jumps to ~50% immediately.
Reported this issue and got marked as resolved when it is clearly not resolved..
Is this still an issue in 1.14.4-pre3 or later? If so, please provide exact reproduction steps.
Of course it is. Have you heard of some attempt to fix the issue? It's not likely to just get old and die on it's own
To reproduce, just start the server; No extra flags needed. No need to even play the game. Just wait until the world initializes, then check the CPU load. You can aggravate the issue if you choose to reproduce within a virtual machine. If you do that, though, then check the host CPU load, not the guest.
Did you read the, multiple, other bug reports that already give exact reproducers?
Lee Ward Being snarky does not help the bug get fixed. If you're not going to contribute any new information, please refrain from commenting.
Agreed. Without the snark, then...
Yes. The problem is still present. Verified by testing 1.14 pre-release 5.
To reproduce:
1) Install the server.jar into an empty directory
2) Change to the directory referred to in step (1) and start the server, per instructions. I.e. "java -Xmx1024M -Xms1024M -jar server.jar nogui"
3) Allow it to error and exit, due to not having accepted the EULA.
4) Edit the EULA file, setting the accepted parameter to true.
5) Start the server again, just as in step (2), above.
6) Monitor ./logs/latest.log, waiting for the "Done" message to appear.
7) Acquire a list of the relevant running threads. On my machine, this looks like:
ps -T -p 707
PID SPID TTY TIME CMD
707 707 pts/0 00:00:00 java
707 708 pts/0 00:00:03 java
707 709 pts/0 00:00:04 VM Thread
707 710 pts/0 00:00:00 Reference Handl
707 711 pts/0 00:00:00 Finalizer
707 712 pts/0 00:00:00 Signal Dispatch
707 713 pts/0 00:00:21 C2 CompilerThre
707 714 pts/0 00:00:02 C1 CompilerThre
707 715 pts/0 00:00:00 Sweeper thread
707 716 pts/0 00:00:00 Common-Cleaner
707 717 pts/0 00:00:00 Service Thread
707 718 pts/0 00:00:00 RMI TCP Accept-
707 719 pts/0 00:00:00 RMI TCP Accept-
707 720 pts/0 00:00:00 RMI TCP Accept-
707 721 pts/0 00:00:00 VM Periodic Tas
707 723 pts/0 00:00:29 Server-Worker-1
707 724 pts/0 00:00:00 Snooper Timer
707 725 pts/0 00:00:00 Server Infinisl
707 726 pts/0 00:03:21 Server thread
707 727 pts/0 00:00:00 Server console
707 728 pts/0 00:00:00 ObjectCleanerTh
707 729 pts/0 00:00:00 Netty Epoll Ser
707 730 pts/0 00:00:00 Server Watchdog
707 736 pts/0 00:00:00 RMI Scheduler(0
707 745 pts/0 00:00:00 JMX server conn
707 794 pts/0 00:00:02 RMI TCP Connect
707 796 pts/0 00:00:02 RMI TCP Connect
8) Find the thread in that list that is using the most CPU; For instance, that thread has ID 726 in the above listing.
9) Trace that process. You will get something like:
...
{tv_sec=0, tv_nsec=708}futex(0x7f16b0b7a2e8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f16b0b7a338, FUTEX_WAIT_PRIVATE, 0,
) = -1 ETIMEDOUT (Connection timed out)
{tv_sec=0, tv_nsec=689}futex(0x7f16b0b7a2e8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f16b0b7a338, FUTEX_WAIT_PRIVATE, 0,
) = -1 ETIMEDOUT (Connection timed out)
{tv_sec=0, tv_nsec=687}futex(0x7f16b0b7a2e8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f16b0b7a338, FUTEX_WAIT_PRIVATE, 0,
) = -1 ETIMEDOUT (Connection timed out)
{tv_sec=0, tv_nsec=701}futex(0x7f16b0b7a2e8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f16b0b7a338, FUTEX_WAIT_PRIVATE, 0,
) = -1 ETIMEDOUT (Connection timed out)
{tv_sec=0, tv_nsec=703}futex(0x7f16b0b7a2e8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f16b0b7a338, FUTEX_WAIT_PRIVATE, 0,
) = -1 ETIMEDOUT (Connection timed out)
{tv_sec=0, tv_nsec=707}futex(0x7f16b0b7a2e8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f16b0b7a338, FUTEX_WAIT_PRIVATE, 0,
) = -1 ETIMEDOUT (Connection timed out)
{tv_sec=0, tv_nsec=699}futex(0x7f16b0b7a2e8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f16b0b7a338, FUTEX_WAIT_PRIVATE, 0,
) = -1 ETIMEDOUT (Connection timed out)
{tv_sec=0, tv_nsec=704}futex(0x7f16b0b7a2e8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f16b0b7a338, FUTEX_WAIT_PRIVATE, 0,
) = -1 ETIMEDOUT (Connection timed out)
{tv_sec=0, tv_nsec=697}futex(0x7f16b0b7a2e8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f16b0b7a338, FUTEX_WAIT_PRIVATE, 0,
) = -1 ETIMEDOUT (Connection timed out)
{tv_sec=0, tv_nsec=714}futex(0x7f16b0b7a2e8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f16b0b7a338, FUTEX_WAIT_PRIVATE, 0,
) = -1 ETIMEDOUT (Connection timed out)
...
These messages repeat, ad nauseum, and without pause.
I also started the server with profiling enabled and have a screenshot of sampling results. I do not see a way to attach that screen shot to this comment, though? The screenshot indicates that two items are collecting all of the runtime. The first is "Server console handler". Under that, it shows that ug$2.run()/java.io.BufferedReader.ReadLine() is very active. The other is "Netty epoll server IO #0" and under that, the active chain is:
java.lang.Thread.run ()
io.netty.util.concurrent.SingleThreadEventExecutor$5.run ()
io.netty.channel.epoll.EpollEventLoop.run ()
io.netty.channel.epoll.EpollEventLoop.epollWait ()
io.netty.channel.epoll.Native.epollWait ()
io.netty.channel.epoll.Native.epollWait0[native] ()
Finally, /proc/interrupts indicates that timer interrupts are increasing at quite a rate:
root@ontest:/home/lee# while true
> do
> grep -i timer /proc/interrupts
> sleep 1
> done
0: 10 IO-APIC 2-edge timer
LOC: 86102299 Local timer interrupts
HVS: 0 Hyper-V stimer0 interrupts
0: 10 IO-APIC 2-edge timer
LOC: 86120146 Local timer interrupts
HVS: 0 Hyper-V stimer0 interrupts
0: 10 IO-APIC 2-edge timer
LOC: 86137633 Local timer interrupts
HVS: 0 Hyper-V stimer0 interrupts
0: 10 IO-APIC 2-edge timer
LOC: 86155141 Local timer interrupts
HVS: 0 Hyper-V stimer0 interrupts
0: 10 IO-APIC 2-edge timer
LOC: 86172589 Local timer interrupts
HVS: 0 Hyper-V stimer0 interrupts
0: 10 IO-APIC 2-edge timer
LOC: 86190086 Local timer interrupts
HVS: 0 Hyper-V stimer0 interrupts
0: 10 IO-APIC 2-edge timer
LOC: 86207560 Local timer interrupts
HVS: 0 Hyper-V stimer0 interrupts
0: 10 IO-APIC 2-edge timer
LOC: 86225069 Local timer interrupts
HVS: 0 Hyper-V stimer0 interrupts
0: 10 IO-APIC 2-edge timer
LOC: 86242565 Local timer interrupts
HVS: 0 Hyper-V stimer0 interrupts
0: 10 IO-APIC 2-edge timer
LOC: 86260068 Local timer interrupts
HVS: 0 Hyper-V stimer0 interrupts
0: 10 IO-APIC 2-edge timer
LOC: 86277560 Local timer interrupts
HVS: 0 Hyper-V stimer0 interrupts
0: 10 IO-APIC 2-edge timer
LOC: 86295081 Local timer interrupts
HVS: 0 Hyper-V stimer0 interrupts
0: 10 IO-APIC 2-edge timer
LOC: 86312563 Local timer interrupts
HVS: 0 Hyper-V stimer0 interrupts
0: 10 IO-APIC 2-edge timer
LOC: 86330096 Local timer interrupts
HVS: 0 Hyper-V stimer0 interrupts
^C
What more can I add?
I figured out how to attach the screenshot. It is Screenshot (1).png in the attached files section.
So I think you're misinterpreting things a fair bit here. A sampling profiler will only tell you what is active within a process, not how much CPU that process is using in the system. The screenshot you posted only says that BufferedReader.readLine() is active 100% of the time, not that it's actually using up any performance. That's because it blocks waiting for input - basically until you input anything in the console, the game could will not even run.
You're also expected to get a lot of activity, because the server still runs 20 ticks per second, so having the thread output a whole lot of stuff is expected. The timeouts on those futex traces do look a bit short, but that could also be normal. Basically, there's very little indication that anything is actually wrong in all of that material.
When I follow your repro steps, the server drops to something like 10% CPU on my VM after the initial world gen is complete.
What exact hardware (and VM software, if any) are you running this on? What is the OS & distro versions?
slicedlime, please comment MC-153712 (Java using 100-200% CPU / MacOS)
I'm sad now
I don't think I'm misinterpreting anything. I provided no interpretation. Only information. After being, rightfully, accused of being "snarky" I deliberately and pedantically shied away from any interpretation, conjecture, supposition, or opinion.
I agree, the profiling information I provided seems virtually useless. It was a piece of information I developed in the course, so I included it. Nothing more, nothing less.
The machine is a server, with an unusual amount of disk. At a high level, though, it is:
CPU: Intel(R) Xeon(R) CPU E3-1246 v3 @ 3.50GHz
Motherboard: ASRock Rack C226 WS+
32GB of ECC-enabled memory
I think that is what you are really asking for but you might want an exhaustive list. If you truly do want an exhaustive inventory of the hardware, do let me know and I can provide it.
Software, on the VM host, versions:
The basic package is an unmodified Debian 9.9 release with all updates applied. Specifically, the kernel is the as-from-debian Linux. It's not been rebooted in awhile so the kernel may be dated. The uname command reports (and reported when the previous info was developed) that the kernel is "tochtli 4.9.0-9-amd64 #1 SMP Debian 4.9.168-1 (2019-04-12) x86_64 GNU/Linux". The package for that kernel is ii linux-image-4.9.0-9-amd64 4.9.168-1+deb9u3 amd64 Linux 4.9 for 64-bit PCs
I am using qemu to host the guest on this machine. dpkg-query reports that the related qemu packages are:
ii ipxe-qemu 1.0.0+git-20161027.b991c67-1 all PXE boot firmware - ROM images for qemu
ii qemu-kvm 1:2.8+dfsg-6+deb9u7 amd64 QEMU Full virtualization on x86 hardware
ii qemu-system-common 1:2.8+dfsg-6+deb9u7 amd64 QEMU full system emulation binaries (common files)
ii qemu-system-x86 1:2.8+dfsg-6+deb9u7 amd64 QEMU full system emulation binaries (x86)
ii qemu-utils 1:2.8+dfsg-6+deb9u7 amd64 QEMU utilities
The hypervisor is managed using libvirt. Those packages are:
ii libvirt-clients 3.0.0-4+deb9u4 amd64 Programs for the libvirt library
ii libvirt-daemon 3.0.0-4+deb9u4 amd64 Virtualization daemon
ii libvirt-daemon-system 3.0.0-4+deb9u4 amd64 Libvirt daemon configuration files
ii libvirt-glib-1.0-0:amd64 1.0.0-1 amd64 libvirt GLib and GObject mapping library
ii libvirt0 3.0.0-4+deb9u4 amd64 library for interfacing with different virtualization systems
ii virt-manager 1:1.4.0-5 all desktop application for managing virtual machines
ii virt-viewer 5.0-1 amd64 Displaying the graphical console of a virtual machine
ii virtinst 1:1.4.0-5 all Programs to create and clone virtual machines
The following XML code is the configuration for the test machine:
<domain type='kvm'>
<name>ontest</name>
<uuid>cb423de8-b80d-43b1-b92d-fb7da6f16cc1</uuid>
<title>Lee Test</title>
<memory unit='KiB'>10485760</memory>
<currentMemory unit='KiB'>10485760</currentMemory>
<vcpu placement='static' current='1'>2</vcpu>
<os>
<type arch='x86_64' machine='pc-i440fx-2.8'>hvm</type>
</os>
<features>
<acpi/>
<apic/>
<vmport state='off'/>
</features>
<cpu mode='host-model'>
<model fallback='allow'/>
<topology sockets='1' cores='2' threads='1'/>
</cpu>
<clock offset='utc'>
<timer name='rtc' tickpolicy='catchup'/>
<timer name='pit' tickpolicy='delay'/>
<timer name='hpet' present='no'/>
</clock>
<on_poweroff>destroy</on_poweroff>
<on_reboot>restart</on_reboot>
<on_crash>restart</on_crash>
<pm>
<suspend-to-mem enabled='no'/>
<suspend-to-disk enabled='no'/>
</pm>
<devices>
<emulator>/usr/bin/kvm</emulator>
<disk type='file' device='disk'>
<driver name='qemu' type='qcow2'/>
<source file='/u1/vm-storage-pools/default/ontest.qcow2'/>
<target dev='vda' bus='virtio'/>
<boot order='1'/>
<address type='pci' domain='0x0000' bus='0x00' slot='0x07' function='0x0'/>
</disk>
<disk type='file' device='cdrom'>
<driver name='qemu' type='raw'/>
<target dev='hda' bus='ide'/>
<readonly/>
<boot order='2'/>
<address type='drive' controller='0' bus='0' target='0' unit='0'/>
</disk>
<controller type='usb' index='0' model='ich9-ehci1'>
<address type='pci' domain='0x0000' bus='0x00' slot='0x05' function='0x7'/>
</controller>
<controller type='usb' index='0' model='ich9-uhci1'>
<master startport='0'/>
<address type='pci' domain='0x0000' bus='0x00' slot='0x05' function='0x0' multifunction='on'/>
</controller>
<controller type='usb' index='0' model='ich9-uhci2'>
<master startport='2'/>
<address type='pci' domain='0x0000' bus='0x00' slot='0x05' function='0x1'/>
</controller>
<controller type='usb' index='0' model='ich9-uhci3'>
<master startport='4'/>
<address type='pci' domain='0x0000' bus='0x00' slot='0x05' function='0x2'/>
</controller>
<controller type='pci' index='0' model='pci-root'/>
<controller type='ide' index='0'>
<address type='pci' domain='0x0000' bus='0x00' slot='0x01' function='0x1'/>
</controller>
<controller type='virtio-serial' index='0'>
<address type='pci' domain='0x0000' bus='0x00' slot='0x06' function='0x0'/>
</controller>
<interface type='bridge'>
<mac address='52:54:00:6e:d6:53'/>
<source bridge='on0'/>
<model type='virtio'/>
<address type='pci' domain='0x0000' bus='0x00' slot='0x03' function='0x0'/>
</interface>
<serial type='pty'>
<target port='0'/>
</serial>
<console type='pty'>
<target type='serial' port='0'/>
</console>
<channel type='unix'>
<target type='virtio' name='org.qemu.guest_agent.0'/>
<address type='virtio-serial' controller='0' bus='0' port='1'/>
</channel>
<channel type='spicevmc'>
<target type='virtio' name='com.redhat.spice.0'/>
<address type='virtio-serial' controller='0' bus='0' port='2'/>
</channel>
<input type='tablet' bus='usb'>
<address type='usb' bus='0' port='1'/>
</input>
<input type='mouse' bus='ps2'/>
<input type='keyboard' bus='ps2'/>
<graphics type='spice' autoport='yes'>
<listen type='address'/>
<image compression='off'/>
</graphics>
<sound model='ich6'>
<address type='pci' domain='0x0000' bus='0x00' slot='0x04' function='0x0'/>
</sound>
<video>
<model type='qxl' ram='65536' vram='65536' vgamem='16384' heads='1' primary='yes'/>
<address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x0'/>
</video>
<redirdev bus='usb' type='spicevmc'>
<address type='usb' bus='0' port='2'/>
</redirdev>
<redirdev bus='usb' type='spicevmc'>
<address type='usb' bus='0' port='3'/>
</redirdev>
<memballoon model='virtio'>
<address type='pci' domain='0x0000' bus='0x00' slot='0x08' function='0x0'/>
</memballoon>
</devices>
</domain>
That guest VM is as it was when I sent the information you are asking about. It's not been updated so I believe all info below reflects the state at that time.
The reported guest CPU info is:
processor : 0
vendor_id : GenuineIntel
cpu family : 6
model : 60
model name : Intel Core Processor (Haswell, no TSX, IBRS)
stepping : 1
microcode : 0x1
cpu MHz : 3499.996
cache size : 16384 KB
physical id : 0
siblings : 1
core id : 0
cpu cores : 1
apicid : 0
initial apicid : 0
fpu : yes
fpu_exception : yes
cpuid level : 13
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ss ht syscall nx pdpe1gb rdtscp lm constant_tsc rep_good nopl xtopology cpuid tsc_known_freq pni pclmulqdq ssse3 fma cx16 pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand hypervisor lahf_lm abm invpcid_single pti ssbd ibrs ibpb fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid xsaveopt arat
bugs : cpu_meltdown spectre_v1 spectre_v2 spec_store_bypass l1tf mds
bogomips : 6999.99
clflush size : 64
cache_alignment : 64
address sizes : 40 bits physical, 48 bits virtual
power management:
A "free -h" reports
total used free shared buff/cache available
Mem: 9.8Gi 79Mi 9.6Gi 8.0Mi 113Mi 9.5Gi
Swap: 0B 0B 0B
The kernel reports, using "uname -a", that it is:
Linux ontest 4.19.0-5-amd64 #1 SMP Debian 4.19.37-3 (2019-05-15) x86_64 GNU/Linux
The package for that kernel is: ii linux-image-4.19.0-5-amd64 4.19.37-3 amd64 Linux 4.19 for 64-bit PCs (signed)
I think the only relevant software would be the JVM packages, no? They are:
ii ca-certificates-java 20190405 all Common CA certificates (JKS keystore)
ii default-jre-headless 2:1.11-71 amd64 Standard Java or Java compatible Runtime (headless)
ii java-common 0.71 all Base package for Java runtimes
ii jdk-11.0.3 11.0.3-1 amd64 Java Platform Standard Edition Development Kit
ii openjdk-11-jre-headless:amd64 11.0.3+1-1 amd64 OpenJDK Java runtime, using Hotspot JIT (headless)
I'd really like to help you avoid wasting all your time trying to exactly duplicate my environment. I believe (have verified in fact) that almost all of the above is, just like the profiling information I sent along, virtually irrelevant. Here is a much more easily accomplished reproducer:
1) Install Debian Linux 9.9 on bare metal.
2) Install the default VM packages. No need for xen, just install kvm+libvirt+qemu and gnome.
3) Login as root, using the gnome desktop. Then, use the gnome VM tool to create a VM. Just take the defaults. Maybe increase the default amount of memory, so there is plenty?
4) Start the newly created guest and install Debian 9.9 (or Debian 10, now) on the guest.
5) Install the jvm and jdk.
6) Post-install, bring any 1.14 server.jar to the guest and start it per the instructions on the Mojang download page.
7) Start minecraft and let it generate the initial world. Then, give it an extra minute or so to quiesce.
On the guest, the CPU load will fall to, or near, 0. On the host, the load will be 100%, minimum.
Now, I'll risk a little interpretation....
At least, the 1.14 minecraft server jars employ a timed mutex that is far, far worse than a "bit short". Look at the strace I sent again. Here is one example of the relevant system call, taken on the guest:
futex(0x7f16b0b7a338, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=699}) = -1 ETIMEDOUT (Connection timed out)
Notice the timeout value? That futex call request has a timeout of 699 nanoseconds; Nano, as in billionths of a second. In your comment above, you noted that the minecraft server clock needs a 20Hz clock. This timeout, though, is many orders of magnitude shorter than that; It's asking for service 69.9 million times a second. My math says that is 3,495,000 times more frequent than the "20 ticks per second" you were discussing.
The story gets worse, though, too. The Linux hypervisor is forced to emulate high-precision timer interrupts. These timers are implemented, both on the bare metal and on the guest, by setting an asynchronous timer to interrupt the operating system once the requested period has elapsed. On bare metal, it can probably be done at this rate but it is an outrageous number of interrupts to handle in any case. For a VM, though, it's practically impossible on today's hardware and, by the way, explains the observed behavior. The guest is requesting a virtual interrupt on the order of 50 - 70 million times a second. Linux hypervisors must virtualize these interrupts and, so, the timer request itself is being trapped or faulted in order for the hypervisor to accomplish that. I.e., all the CPU load is attributed to the hypervisor, and, since, the guest isn't even running while that is going on it sees no load at all.
Then, worse yet. The resolution of the high-precision timers under hypervisors on Linux is on the order of 10's of microseconds. However, here, the requested timeout is at least one order of magnitude smaller than that. Put another way, the timeout is attempting to trigger on clock noise, not actual values.
Given the rate at which /proc/interrupts reports the timer interrupts growing on the guest for what I reported above, I would estimate that the hypervisor on my machine only capable of emulating somewhere around 17,847 timer interrupts per second.
Which implies, to me, that a timeout value less than about 56 microseconds is, at best, pointless. Even that, value, though, would obviously only reproduce the 100% host load we are currently observing.
Moving beyond interpretation to complete conjecture and supposition, now. The minecraft server seems to have an asynchronous timer that is egregiously parameterized. I suspect relating to the networking code. Did someone, somewhere, somewhen, perhaps believe that a very short timeout would improve the network latency observed by the client? Good thought. Perhaps, though, the very low latency service desire is better thought of in the milliseconds time-frame as opposed to the sub-microsecond time-frame, though?
More specifically... If the server only updates 20 times per second, in other words a 50 millisecond period, then maybe we could agree that 50ms is the Nyquist frequency for any sampling? If we could agree on that, then, isn't a 25 millisecond timeout fast enough? Anything shorter than that should have no observable effect, right?
Whatever the reason though, clearly that sub-microsecond mutex call needs some love.
By the way, here is a small C program that reproduces the symptoms. It just concretely demonstrates that the Linux host-side of the virtualized machine is in no way capable of handling the requested timeout value. Just compile and run on the guest. Note that the guest load is 0, while one core on the host is completely consumed.
#include <stdint.h>
#include <time.h>
#include <assert.h>
#include <errno.h>
#include <unistd.h>
#include <sys/syscall.h>
#include <linux/futex.h>
int futex(uint32_t *uaddr, int futex_op, int val, const struct timespec *timeout, int *uaddr2, int val3);
int
{ uint32_t u; struct timespec t = \{ 0, 780 }main()
;
int i;
u = 0;
for (;
(void )futex(&u, FUTEX_WAIT|FUTEX_PRIVATE_FLAG, u, &t, &u, 0);
// Not reached.
return 0;
}
int
futex(uint32_t *uaddr, int futex_op, int val, const struct timespec *timeout, int *uaddr2, int val3)
{
return syscall(SYS_futex, uaddr, futex_op, val, timeout, uaddr2, val3);
}
Sorry for the ugly formatting...
Apologies. I just read my latest through one more time. Two errors...
1) When describing the guest software version I forgot to note that the base install was Debian 10. Yes, 9.9 on the host, still, but 10 on the guest.
2) When discussing a more appropriate timeout value, I misspoke. 50 ms is the, assumed, rate and not the Nyquist frequency. I suggested the Nyquist frequency as a minimum, permissible, timeout. I really do know the definition for Nyquist frequency, in spite of my idiotic usage. Sorry.
Is the overloaded hypervisor handling of futexes the root cause? Perhaps its a case where the hypervisor is overloaded and would be able to somewhat cope on bare metal, and the root cause being that the way the code is handling its executor service is using an incorrect allocation of threads, based on the cores reported by the Runtime's availableProcessors() method, which in turn may be incorrect on hypervisors and VMs.
The latter, has been a known issue in the past for Java 6 through 9. Coupled with the bug in SystemUtils for incorrectly allocating the direct executor service when there is only one core. So, it's quite possible that the futexes are being overloaded because the system is time-slicing to handle the threads that exceed the number of cores, whether caused by the bug, or by the Runtime reporting the full system cores, rather than the VM specific cores.
The bug, I'm referring to on SystemUtils is that it can never reach the code to use the direct executor service over the fork join pool in the case of a single core, because the available cores minus one is being clamped to a value 1 to 7. At least, it was that way in 1.14.3.
If I recall correctly, it would stall on 0% when creating the spawn areas, waiting for the main thread to finish because it couldn't allocate the worker thread in the pool on a single core.
But the more relevant concern is the whether the availableProcessors() method on that particular JVM under your VM is reporting the correct value (all the time). Because it had been reported that on some VMs it could report only one core, or might report the hardware number of cores, not the number allocated to the VM.
Well, I don't know of course. I don't have access to the server code. The server does not appear to be stalling at start, though. World generation seems to proceed smoothly in the reproducer, above. Restart of an existing, production, 1.14.3, server also seems to proceed smoothly. For that same, existing, server the symptoms on the virtual guest include:
1) An, infrequent, number of can't-keep-up-messages when the server is completely idle and a veritable barrage of same when there are players present.
2) On the production guest, I configure the CPU as pass-through and include the TSC clock. When that configuration is used the guest kernel reports that the TSC is behaving badly, enough to be unusable, and switches to the HPET timer-counter.
3) Persistent lag and rubber-banding behaviors during game play. Network does not seem to matter. It happens to players on long-haul links and on the (10 Gb/s wired) LAN.
On the host side, when the server is idle CPU load hovers around 100 to 103 percent. It goes up only a small amount when players are present.
Most of those symptoms are displayed by the reproducer I gave. I tried to simplify the reproducer by using the generic qemu CPU (Haswell) and I didn't enable the TSC. Also, I only tried game-play from the wired LAN.
Do those symptoms sound like they might be related to this JVM availableProcessors() bug you are talking about? If so, do you have a workaround you would care to share?
Hard to say if they are related. HPET is per system and higher precision, but uses more resources, but allows for better sync when usign multiple cores. Whereas TSC is per CPU and faster, and synchronizes across all cores on Nehalem+ CPUs.
Might want to try both HPET standalone, and TSC with HPET as a backup.
If your core is spending a lot of time servicing interrupts, then changing these could help.
Also, not sure if it will help, but there is a difference in running a server in SMP vs. Pre-Empt, or an actual Realtime kernel. As these will also affect interrupts and their priorities.
Did you try yet with -pre6 ? I've heard other reports that from pre5 to pre6, some had an improvement in performance.
I did that. The production VM is configured with both clocks. The kernel, on the guest and very quickly after the minecraft server starts, reports that the TSC is unusable and switches to HPET. The test VM is configured HPET only. Both configurations reliably reproduce the problems.