search

adoptium / adoptium-support

For end-user problems reported with our binary distributions
Apache License 2.0
44 stars 15 forks source link

ARM32 / Raspberry Pi 3 - TieredCompilation does not seem to work #225

Closed jocull closed 3 years ago

jocull commented 3 years ago

Summary

-XX:+TieredCompilation does not seem to work on ARM32 (Raspberry Pi 3 hardware). When I set this flag, I can see in jstack that the C1 and C2 threads are present, but they do not seem to be doing anything. The application runs slow, as if it is running fully on the interpreter.

Steps to reproduce

I have been testing this with the latest Minecraft server jar (1.16.4). A simple setup will reproduce it.

$ java -version
openjdk version "15.0.1" 2020-10-20
OpenJDK Runtime Environment AdoptOpenJDK (build 15.0.1+9)
OpenJDK Server VM AdoptOpenJDK (build 15.0.1+9, mixed mode)

$ java -Xmx512 -XX:+TieredCompilation -jar server.jar nogui

Expected results

Improved performance, active C1 + C2 compiler threads.

Actual results

Sluggish performance, followed by eventual application lock up (all threads waiting on a monitor I can't pin down)

Triaging info

Java version:

openjdk version "15.0.1" 2020-10-20
OpenJDK Runtime Environment AdoptOpenJDK (build 15.0.1+9)
OpenJDK Server VM AdoptOpenJDK (build 15.0.1+9, mixed mode)

What is your operating system and platform?

$ cat /etc/os-release
PRETTY_NAME="Raspbian GNU/Linux 9 (stretch)"
NAME="Raspbian GNU/Linux"
VERSION_ID="9"
VERSION="9 (stretch)"
VERSION_CODENAME=stretch
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"

How did you install Java?

I tried both direct tar.gz download and installing from Apt repo.

Did it work before? Did you test with other Java versions?

Yes, it works in JDK9 from Raspbian's apt. It also appears to work in AdoptOpenJDK 11 (LTS).

$ java -version
openjdk version "11.0.9.1" 2020-11-04
OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.9.1+1)
OpenJDK Server VM AdoptOpenJDK (build 11.0.9.1+1, mixed mode)
aahlenst commented 3 years ago

I don't have much time at the moment. Can you please search in https://bugs.openjdk.java.net/secure/Dashboard.jspa whether anything pops up and also test with a download from https://bell-sw.com/pages/downloads/#/java-15-current?

jocull commented 3 years ago

I tried "Liberica Standard JRE 15.0.1+9 ARM 32 bit for Linux" from tar.gz (Sha1 d236b1ca819428ea3fcc4bc64faad7a1a9b76b5c) and it appears to have the same issue.

Nothing turned up in a search, but this is the closest thing I was able to find. This issue is not listed as specific to ARM: https://bugs.openjdk.java.net/browse/JDK-8202168

karianna commented 3 years ago

@sxa I don't think we saw this on our Pi builds?

jocull commented 3 years ago

@sxa I don't think we saw this on our Pi builds?

It could be a conflict with the version of Raspbian I have installed - I think it is possibly an outdated version. I have it posted in the original report above if you want to compare.

aahlenst commented 3 years ago

Relevant part of jstack on a Raspberrry Pi 4B in 32 bit mode:

"C2 CompilerThread0" #6 daemon prio=9 os_prio=0 cpu=13286.04ms elapsed=65.01s tid=0x8997f900 nid=0x14c1 waiting on condition  [0x00000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"C1 CompilerThread0" #8 daemon prio=9 os_prio=0 cpu=4124.21ms elapsed=65.01s tid=0x89981f30 nid=0x14c2 waiting on condition  [0x00000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

I looks like both threads did something. I cannot say anything about the performance of Minecraft because I've never played it.

PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"
NAME="Raspbian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"
aahlenst commented 3 years ago

Entry point for test runs in TRSS: https://trss.adoptopenjdk.net/allTestsInfo?buildId=5fdaa8d52bad78506697c70e

I don't see any big slowness apart from the usual machine differences (the Scaleway ones are very slow).

jocull commented 3 years ago

Two differences here would be worth validating independently -- Pi 3 vs Pi 4 hardware, and Raspbian 9 vs 10.

I can see about getting Raspbian 10 loaded up on my Pi 3 and check for improvements. I don't have a Pi 4 on hand yet, but would anyone have a Pi 4 with Raspbian 9?

aahlenst commented 3 years ago

Older Raspbians do not boot on the Raspberry Pi 4.

jocull commented 3 years ago

I see the same performance issue with AdoptOpenJDK 15 on Raspbian 10 (Buster)

$ cat /etc/os-release 
PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"
NAME="Raspbian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"

Here is some additional information about the hardware I'm testing on as well:

$ cat /proc/cpuinfo 
processor       : 0
model name      : ARMv7 Processor rev 4 (v7l)
BogoMIPS        : 76.80
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm crc32 
CPU implementer : 0x41
CPU architecture: 7
CPU variant     : 0x0
CPU part        : 0xd03
CPU revision    : 4

processor       : 1
model name      : ARMv7 Processor rev 4 (v7l)
BogoMIPS        : 76.80
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm crc32 
CPU implementer : 0x41
CPU architecture: 7
CPU variant     : 0x0
CPU part        : 0xd03
CPU revision    : 4

processor       : 2
model name      : ARMv7 Processor rev 4 (v7l)
BogoMIPS        : 76.80
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm crc32 
CPU implementer : 0x41
CPU architecture: 7
CPU variant     : 0x0
CPU part        : 0xd03
CPU revision    : 4

processor       : 3
model name      : ARMv7 Processor rev 4 (v7l)
BogoMIPS        : 76.80
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm crc32 
CPU implementer : 0x41
CPU architecture: 7
CPU variant     : 0x0
CPU part        : 0xd03
CPU revision    : 4

Hardware        : BCM2835
Revision        : a22082
Serial          : xxxxxxxxxxxxxxxxxxxxxxx
Model           : Raspberry Pi 3 Model B Rev 1.2

This is a fresh install. Is there anything I can do to help debug or test further? I can try to pin down the breaking point in major JDK releases. The package manager's default JDK 11 was OK so far.

jocull commented 3 years ago

AdoptOpenJDK 14 seems to work fine:

openjdk version "14.0.2" 2020-07-14
OpenJDK Runtime Environment AdoptOpenJDK (build 14.0.2+12)
OpenJDK Server VM AdoptOpenJDK (build 14.0.2+12, mixed mode, sharing)
aahlenst commented 3 years ago

@jocull It would be good if you could provide more details, for example jstack output of different versions (working and not working), vmstat output. Checking with nightlies of 16 is a good idea, too. Also helpful would be a small program that reproduces the problem. Running a Minecraft server isn't ideal. The next step would be to find someone who can look into it. @karianna has some ARM and JVM experts in his team. Otherwise, you'd need to reach out to OpenJDK.

jocull commented 3 years ago

I will see what I can gather or create there. Do nightlies exist for arm32? I didn’t see any there 😕

I noticed also that JDK 13 seemed stable, but JDK 14 crashed. I can try to attach those crash logs later, but they may be irrelevant.

aahlenst commented 3 years ago

Maybe the API has an hiccup again. You can pull the nightlies from https://github.com/AdoptOpenJDK/openjdk16-binaries/releases. Expand the latest tag and search for "arm".

jocull commented 3 years ago

That worked, thanks! I have a nightly JDK 16 now. Trying to figure out how to get attachments to work with the logs and information that I do have.

$ ./java -version
openjdk version "16" 2021-03-16
OpenJDK Runtime Environment AdoptOpenJDK (build 16+8-202012220416)
OpenJDK Server VM AdoptOpenJDK (build 16+8-202012220416, mixed mode)
jocull commented 3 years ago

Here are the files I have. adoptopenjdk-support-issues-225-jdk-outputs.zip

output-jdk10.log - Stdout from Raspbian's bundled JDK 10 output-jdk16.log - Stdout from nightly posted above jstack-16.log - jstack -l output from the nightly posted above

In the jstack output you can see the threads appear blocked, and from the corresponding output the server was never successfully booted. In JDK 10 logs you can see [Server thread/INFO]: Done where the process completes (mixed in with stdout).

"Worker-Main-4" #20 daemon prio=5 os_prio=0 cpu=2517.22ms elapsed=7105.30s tid=0x47011ef8 nid=0x71a6 waiting for monitor entry  [0x46678000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at java.util.zip.ZipFile.getEntry(java.base@16/ZipFile.java:326)
    - waiting to lock <0x4b06fb38> (a sun.net.www.protocol.jar.URLJarFile)
    at java.util.jar.JarFile.getEntry(java.base@16/JarFile.java:514)

...

"Worker-Main-6" #22 daemon prio=5 os_prio=0 cpu=2122.80ms elapsed=7105.28s tid=0x4a6058f0 nid=0x71a8 waiting for monitor entry  [0x4623c000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at java.util.zip.ZipFile$ZipFileInputStream.read(java.base@16/ZipFile.java:926)
    - waiting to lock <0x4b06fb38> (a sun.net.www.protocol.jar.URLJarFile)
    at java.util.zip.ZipFile$ZipFileInflaterInputStream.fill(java.base@16/ZipFile.java:445)

Here are the full flags each JVM is running with.

java \
        -Xms512M \
        -Xmx512M \
        -XX:+UnlockExperimentalVMOptions \
        -XX:+UnlockDiagnosticVMOptions \
        -XX:+PrintCompilation \
        -XX:+LogCompilation \
        -XX:+PrintCodeCache \
        -XX:-PrintCodeCacheOnCompilation \
        -XX:+TieredCompilation \
        -XX:MaxInlineLevel=30 \
        -XX:FreqInlineSize=325 \
        -XX:+AlwaysPreTouch \
        -XX:+DisableExplicitGC \
        -XX:+UseG1GC \
        -XX:G1HeapRegionSize=16M \
        -XX:MaxGCPauseMillis=50 \
        -XX:G1MixedGCLiveThresholdPercent=70 \
        -XX:+ParallelRefProcEnabled \
        -Xlog:gc*,safepoint=info:file=gc.log:uptimemillis:filecount=4,filesize=50M \
        --show-version \
        -jar minecraft-server-1.16.4.jar nogui

This is somewhat anecdotal, but comparing the -XX:+PrintCompilation outputs between 10 and 16 seems to show that JDK 16 is compiling at a lower "complexity" level if I'm reading the output right. Many more 2 than 3 or 4 reported. I do wonder if there is just a default JVM flag that was changed between versions and that is what is causing these differences between the various versions of the JDK.

aahlenst commented 3 years ago

I spent some time with a Raspberry Pi 3 on Raspbian 10 and various OpenJDKs. I looked how long the different JDKs took to reach the same point according to the log output. The Raspberry Pi 3 had no active cooling and only an SD card and I did every experiment only once, so it's not very scientific. But still, I'm not convinced that the original hypothesis ("The application runs slow, as if it is running fully on the interpreter.") is true.

pi@raspberrypi:~/Downloads $ jdk-15.0.1+9/bin/java -Xmx512M -Xms512M -jar server.jar nogui
[13:59:35] [main/INFO]: Environment: authHost='https://authserver.mojang.com', accountsHost='https://api.mojang.com', sessionHost='https://sessionserver.mojang.com', servicesHost='https://api.minecraftservices.com', name='PROD'
[13:59:42] [main/WARN]: Ambiguity between arguments [teleport, destination] and [teleport, targets] with inputs: [Player, 0123, @e, dd12be42-52a9-4a91-a8a1-11c01849e498]
[13:59:42] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[13:59:42] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, targets] with inputs: [0.1 -0.5 .9, 0 0 0]
[13:59:42] [main/WARN]: Ambiguity between arguments [teleport, targets] and [teleport, destination] with inputs: [Player, 0123, dd12be42-52a9-4a91-a8a1-11c01849e498]
[13:59:43] [main/WARN]: Ambiguity between arguments [teleport, targets, location] and [teleport, targets, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[13:59:43] [main/INFO]: Reloading ResourceManager: Default
[13:59:54] [Worker-Main-4/INFO]: Loaded 7 recipes
[13:59:57] [Worker-Main-4/INFO]: Loaded 927 advancements
[14:00:20] [Server thread/INFO]: Starting minecraft server version 1.16.4
[14:00:20] [Server thread/WARN]: To start the server with more ram, launch it as "java -Xmx1024M -Xms1024M -jar minecraft_server.jar"
[14:00:20] [Server thread/INFO]: Loading properties
[14:00:20] [Server thread/INFO]: Default game type: SURVIVAL
[14:00:20] [Server thread/INFO]: Generating keypair
[14:00:24] [Server thread/INFO]: Starting Minecraft server on *:25565
[14:00:25] [Server thread/INFO]: Using default channel type
[14:00:26] [Server thread/INFO]: Preparing level "world"

AdoptOpenJDK 15.0.1 needs 51s to reach "Preparing level 'world'".

pi@raspberrypi:~/Downloads $ jdk-14.0.2+12/bin/java -Xmx512M -Xms512M -jar server.jar nogui
[14:09:40] [main/INFO]: Environment: authHost='https://authserver.mojang.com', accountsHost='https://api.mojang.com', sessionHost='https://sessionserver.mojang.com', servicesHost='https://api.minecraftservices.com', name='PROD'
[14:09:50] [main/WARN]: Ambiguity between arguments [teleport, destination] and [teleport, targets] with inputs: [Player, 0123, @e, dd12be42-52a9-4a91-a8a1-11c01849e498]
[14:09:50] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:09:51] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, targets] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:09:51] [main/WARN]: Ambiguity between arguments [teleport, targets] and [teleport, destination] with inputs: [Player, 0123, dd12be42-52a9-4a91-a8a1-11c01849e498]
[14:09:51] [main/WARN]: Ambiguity between arguments [teleport, targets, location] and [teleport, targets, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:09:51] [main/INFO]: Reloading ResourceManager: Default
[14:10:03] [Worker-Main-4/INFO]: Loaded 7 recipes
[14:10:08] [Worker-Main-4/INFO]: Loaded 927 advancements
[14:10:23] [Server thread/INFO]: Starting minecraft server version 1.16.4
[14:10:23] [Server thread/WARN]: To start the server with more ram, launch it as "java -Xmx1024M -Xms1024M -jar minecraft_server.jar"
[14:10:23] [Server thread/INFO]: Loading properties
[14:10:23] [Server thread/INFO]: Default game type: SURVIVAL
[14:10:23] [Server thread/INFO]: Generating keypair
[14:10:26] [Server thread/INFO]: Starting Minecraft server on *:25565
[14:10:26] [Server thread/INFO]: Using default channel type
[14:10:28] [Server thread/INFO]: Preparing level "world"

AdoptOpenJDK 14.0.2 needs 48s.

pi@raspberrypi:~/Downloads $ jdk-11.0.9.1+1/bin/java -Xmx512M -Xms512M -jar server.jar nogui
[14:18:26] [main/INFO]: Environment: authHost='https://authserver.mojang.com', accountsHost='https://api.mojang.com', sessionHost='https://sessionserver.mojang.com', servicesHost='https://api.minecraftservices.com', name='PROD'
[14:18:35] [main/WARN]: Ambiguity between arguments [teleport, destination] and [teleport, targets] with inputs: [Player, 0123, @e, dd12be42-52a9-4a91-a8a1-11c01849e498]
[14:18:35] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:18:36] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, targets] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:18:36] [main/WARN]: Ambiguity between arguments [teleport, targets] and [teleport, destination] with inputs: [Player, 0123, dd12be42-52a9-4a91-a8a1-11c01849e498]
[14:18:36] [main/WARN]: Ambiguity between arguments [teleport, targets, location] and [teleport, targets, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:18:36] [main/INFO]: Reloading ResourceManager: Default
[14:18:48] [Worker-Main-4/INFO]: Loaded 7 recipes
[14:18:53] [Worker-Main-4/INFO]: Loaded 927 advancements
[14:19:09] [Server thread/INFO]: Starting minecraft server version 1.16.4
[14:19:09] [Server thread/WARN]: To start the server with more ram, launch it as "java -Xmx1024M -Xms1024M -jar minecraft_server.jar"
[14:19:09] [Server thread/INFO]: Loading properties
[14:19:10] [Server thread/INFO]: Default game type: SURVIVAL
[14:19:10] [Server thread/INFO]: Generating keypair
[14:19:15] [Server thread/INFO]: Starting Minecraft server on *:25565
[14:19:15] [Server thread/INFO]: Using default channel type
[14:19:17] [Server thread/INFO]: Preparing level "world"

AdoptOpenJDK 11.0.9.1 needs 51s.

pi@raspberrypi:~/Downloads $ jdk-15.0.1/bin/java -Xmx512M -Xms512M -jar server.jar nogui
[14:21:25] [main/INFO]: Environment: authHost='https://authserver.mojang.com', accountsHost='https://api.mojang.com', sessionHost='https://sessionserver.mojang.com', servicesHost='https://api.minecraftservices.com', name='PROD'
[14:21:32] [main/WARN]: Ambiguity between arguments [teleport, destination] and [teleport, targets] with inputs: [Player, 0123, @e, dd12be42-52a9-4a91-a8a1-11c01849e498]
[14:21:32] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:21:32] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, targets] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:21:32] [main/WARN]: Ambiguity between arguments [teleport, targets] and [teleport, destination] with inputs: [Player, 0123, dd12be42-52a9-4a91-a8a1-11c01849e498]
[14:21:32] [main/WARN]: Ambiguity between arguments [teleport, targets, location] and [teleport, targets, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:21:32] [main/INFO]: Reloading ResourceManager: Default
[14:21:43] [Worker-Main-4/INFO]: Loaded 7 recipes
[14:21:47] [Worker-Main-4/INFO]: Loaded 927 advancements
[14:22:04] [Server thread/INFO]: Starting minecraft server version 1.16.4
[14:22:04] [Server thread/WARN]: To start the server with more ram, launch it as "java -Xmx1024M -Xms1024M -jar minecraft_server.jar"
[14:22:04] [Server thread/INFO]: Loading properties
[14:22:04] [Server thread/INFO]: Default game type: SURVIVAL
[14:22:04] [Server thread/INFO]: Generating keypair
[14:22:08] [Server thread/INFO]: Starting Minecraft server on *:25565
[14:22:08] [Server thread/INFO]: Using default channel type
[14:22:09] [Server thread/INFO]: Preparing level "world"

Bell Soft Liberica 15.0.1 needs 44s.

pi@raspberrypi:~/Downloads $ zulu11.43.100-ca-jdk11.0.9.1-linux_aarch32hf/bin/java -Xmx512M -Xms512M -jar server.jar nogui
[14:25:36] [main/INFO]: Environment: authHost='https://authserver.mojang.com', accountsHost='https://api.mojang.com', sessionHost='https://sessionserver.mojang.com', servicesHost='https://api.minecraftservices.com', name='PROD'
[14:25:40] [main/WARN]: Ambiguity between arguments [teleport, destination] and [teleport, targets] with inputs: [Player, 0123, @e, dd12be42-52a9-4a91-a8a1-11c01849e498]
[14:25:40] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:25:40] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, targets] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:25:40] [main/WARN]: Ambiguity between arguments [teleport, targets] and [teleport, destination] with inputs: [Player, 0123, dd12be42-52a9-4a91-a8a1-11c01849e498]
[14:25:40] [main/WARN]: Ambiguity between arguments [teleport, targets, location] and [teleport, targets, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:25:40] [main/INFO]: Reloading ResourceManager: Default
[14:25:49] [Worker-Main-4/INFO]: Loaded 7 recipes
[14:25:51] [Worker-Main-4/INFO]: Loaded 927 advancements
[14:26:02] [Server thread/INFO]: Starting minecraft server version 1.16.4
[14:26:02] [Server thread/WARN]: To start the server with more ram, launch it as "java -Xmx1024M -Xms1024M -jar minecraft_server.jar"
[14:26:02] [Server thread/INFO]: Loading properties
[14:26:02] [Server thread/INFO]: Default game type: SURVIVAL
[14:26:02] [Server thread/INFO]: Generating keypair
[14:26:03] [Server thread/INFO]: Starting Minecraft server on *:25565
[14:26:04] [Server thread/INFO]: Using default channel type
[14:26:08] [Server thread/INFO]: Preparing level "world"

Azul Zulu 11.0.9 needs 32s.

Switching everything off so that we only have the interpreter working:

jdk-15.0.1+9/bin/java -Xint -Xmx512M -Xms512M -jar server.jar nogui
[14:31:49] [main/INFO]: Environment: authHost='https://authserver.mojang.com', accountsHost='https://api.mojang.com', sessionHost='https://sessionserver.mojang.com', servicesHost='https://api.minecraftservices.com', name='PROD'
[14:32:00] [main/WARN]: Ambiguity between arguments [teleport, destination] and [teleport, targets] with inputs: [Player, 0123, @e, dd12be42-52a9-4a91-a8a1-11c01849e498]
[14:32:00] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:32:00] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, targets] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:32:00] [main/WARN]: Ambiguity between arguments [teleport, targets] and [teleport, destination] with inputs: [Player, 0123, dd12be42-52a9-4a91-a8a1-11c01849e498]
[14:32:00] [main/WARN]: Ambiguity between arguments [teleport, targets, location] and [teleport, targets, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:32:00] [main/INFO]: Reloading ResourceManager: Default
[14:34:14] [Worker-Main-4/INFO]: Loaded 7 recipes
[14:34:21] [Worker-Main-4/INFO]: Loaded 927 advancements

Didn't have the patience to wait any longer.

pi@raspberrypi:~/Downloads $ jdk-15.0.1+9/bin/java -XX:TieredStopAtLevel=1 -Xmx512M -Xms512M -jar server.jar nogui
[14:36:07] [main/INFO]: Environment: authHost='https://authserver.mojang.com', accountsHost='https://api.mojang.com', sessionHost='https://sessionserver.mojang.com', servicesHost='https://api.minecraftservices.com', name='PROD'
[14:36:14] [main/WARN]: Ambiguity between arguments [teleport, destination] and [teleport, targets] with inputs: [Player, 0123, @e, dd12be42-52a9-4a91-a8a1-11c01849e498]
[14:36:14] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:36:14] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, targets] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:36:14] [main/WARN]: Ambiguity between arguments [teleport, targets] and [teleport, destination] with inputs: [Player, 0123, dd12be42-52a9-4a91-a8a1-11c01849e498]
[14:36:14] [main/WARN]: Ambiguity between arguments [teleport, targets, location] and [teleport, targets, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:36:14] [main/INFO]: Reloading ResourceManager: Default
[14:36:25] [Worker-Main-4/INFO]: Loaded 7 recipes
[14:36:29] [Worker-Main-4/INFO]: Loaded 927 advancements
[14:36:44] [Server thread/INFO]: Starting minecraft server version 1.16.4
[14:36:44] [Server thread/WARN]: To start the server with more ram, launch it as "java -Xmx1024M -Xms1024M -jar minecraft_server.jar"
[14:36:44] [Server thread/INFO]: Loading properties
[14:36:44] [Server thread/INFO]: Default game type: SURVIVAL
[14:36:45] [Server thread/INFO]: Generating keypair
[14:36:47] [Server thread/INFO]: Starting Minecraft server on *:25565
[14:36:48] [Server thread/INFO]: Using default channel type
[14:36:49] [Server thread/INFO]: Preparing level "world"

AdoptOpenJDK 15.0.1 with C1 only took 42s.

In any test, I couldn't observe excessive blocked threads in jstack, either. But what I could observe: Overheating CPU, lots of threads waiting for CPU time.

The Raspberry Pi 4 with active cooling and a proper SSD is significantly faster:

$ jdk-15.0.1+9/bin/java -Xmx512M -Xms512M -jar server.jar nogui
[14:04:49] [main/INFO]: Environment: authHost='https://authserver.mojang.com', accountsHost='https://api.mojang.com', sessionHost='https://sessionserver.mojang.com', servicesHost='https://api.minecraftservices.com', name='PROD'
[14:04:52] [main/WARN]: Ambiguity between arguments [teleport, destination] and [teleport, targets] with inputs: [Player, 0123, @e, dd12be42-52a9-4a91-a8a1-11c01849e498]
[14:04:52] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:04:52] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, targets] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:04:53] [main/WARN]: Ambiguity between arguments [teleport, targets] and [teleport, destination] with inputs: [Player, 0123, dd12be42-52a9-4a91-a8a1-11c01849e498]
[14:04:53] [main/WARN]: Ambiguity between arguments [teleport, targets, location] and [teleport, targets, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:04:53] [main/INFO]: Reloading ResourceManager: Default
[14:04:57] [Worker-Main-4/INFO]: Loaded 7 recipes
[14:04:59] [Worker-Main-4/INFO]: Loaded 927 advancements
[14:05:06] [Server thread/INFO]: Starting minecraft server version 1.16.4
[14:05:06] [Server thread/INFO]: Loading properties
[14:05:06] [Server thread/INFO]: Default game type: SURVIVAL
[14:05:06] [Server thread/INFO]: Generating keypair
[14:05:08] [Server thread/INFO]: Starting Minecraft server on *:25565
[14:05:08] [Server thread/INFO]: Using default channel type
[14:05:08] [Server thread/INFO]: Preparing level "world"
[14:05:11] [Server thread/WARN]: Unable to find spawn biome

If you still think there's something wrong, please provide some hard numbers and something that's easy to reproduce. Starting a Minecraft server isn't the best choice.

This is somewhat anecdotal, but comparing the -XX:+PrintCompilation outputs between 10 and 16 seems to show that JDK 16 is compiling at a lower "complexity" level if I'm reading the output right.

This is definitely not my area of expertise. Just a thought: The JDK has changed a lot between 10 and 16.

aahlenst commented 3 years ago

I managed to make myself look like a fool again by not realizing that TieredCompilation is off by default on ARM. Indeed, if I enable TieredCompilation on any Raspberry Pi that I have (3, various 4 models), then Minecraft hangs after some time:

https://github.com/openjdk/jdk/blob/b575dd80b6e86821fcf3e065e31c6bddb85db6c4/src/hotspot/cpu/arm/c1_globals_arm.hpp#L42

$ jdk-15.0.1+9/bin/java -XX:+TieredCompilation -Xmx512M -Xms512M -jar server.jar nogui
[14:41:55] [main/INFO]: Environment: authHost='https://authserver.mojang.com', accountsHost='https://api.mojang.com', sessionHost='https://sessionserver.mojang.com', servicesHost='https://api.minecraftservices.com', name='PROD'
[14:41:57] [main/WARN]: Ambiguity between arguments [teleport, destination] and [teleport, targets] with inputs: [Player, 0123, @e, dd12be42-52a9-4a91-a8a1-11c01849e498]
[14:41:58] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:41:58] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, targets] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:41:58] [main/WARN]: Ambiguity between arguments [teleport, targets] and [teleport, destination] with inputs: [Player, 0123, dd12be42-52a9-4a91-a8a1-11c01849e498]
[14:41:58] [main/WARN]: Ambiguity between arguments [teleport, targets, location] and [teleport, targets, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[14:41:58] [main/INFO]: Reloading ResourceManager: Default
[14:42:01] [Worker-Main-4/INFO]: Loaded 7 recipes
[14:42:03] [Worker-Main-4/INFO]: Loaded 927 advancements

jstack claims some thread deadlocked:

Found one Java-level deadlock:
=============================
"main":
  waiting to lock monitor 0x89f45cc0 (object 0x8bc09618, a java.util.jar.JarFile),
  which is held by UNKNOWN_owner_addr=0x854147d8

Java stack information for the threads listed above:
===================================================
"main":
    at java.util.zip.ZipFile.getEntry(java.base@15.0.1/ZipFile.java:326)
    - waiting to lock <0x8bc09618> (a java.util.jar.JarFile)
    at java.util.jar.JarFile.getEntry(java.base@15.0.1/JarFile.java:510)
    at java.util.jar.JarFile.getJarEntry(java.base@15.0.1/JarFile.java:465)
    at jdk.internal.loader.URLClassPath$JarLoader.getResource(java.base@15.0.1/URLClassPath.java:932)
    at jdk.internal.loader.URLClassPath.getResource(java.base@15.0.1/URLClassPath.java:317)
    at jdk.internal.loader.BuiltinClassLoader.findClassOnClassPathOrNull(java.base@15.0.1/BuiltinClassLoader.java:720)
    at jdk.internal.loader.BuiltinClassLoader.loadClassOrNull(java.base@15.0.1/BuiltinClassLoader.java:646)
    - locked <0x93be9030> (a java.lang.Object)
    at jdk.internal.loader.BuiltinClassLoader.loadClass(java.base@15.0.1/BuiltinClassLoader.java:604)
    at jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(java.base@15.0.1/ClassLoaders.java:168)
    at java.lang.ClassLoader.loadClass(java.base@15.0.1/ClassLoader.java:522)
    at ceg$a.a(SourceFile:643)
    at bup$$Lambda$3257/0x850c18a8.accept(Unknown Source)
    at java.lang.Iterable.forEach(java.base@15.0.1/Iterable.java:75)
    at bup.a(SourceFile:892)
    at aen.e(SourceFile:24)
    at vz.i(SourceFile:88)
    at net.minecraft.server.Main.main(SourceFile:144)

Found 1 deadlock.

That TieredCompilation is off by default explains why we haven't seen performance problems in our tests. I didn't find any indication that tiered compilation is supposed to work on ARM, so the interesting question would be: Why do you think it should work, @jocull?

jocull commented 3 years ago

You got it! Tiered is off by default, but works very well on earlier JDK versions and doesn’t simply exit the JVM to report it is “Unsupported” like other unsupported features would. That is why I think it should work now or explicitly tell me otherwise 😄 I haven’t ever seen documentation that states tiered isn’t supported on ARM hardware.

aahlenst commented 3 years ago

I haven’t ever seen documentation that states tiered isn’t supported on ARM hardware.

I think it's supposed to be the other way around with all advanced features (GCs, intrinsics, ...): If it isn't explicitly supported, assume it isn't.

So, what are we going to do now? Close the issue?

jocull commented 3 years ago

It would be great to get clarification from the JDK team on whether or not tiered compilation is supposed to be supported on ARM. The C1 and C2 compilers both seem to function, and historically have functioned, but something has made the behavior change recently.

Tiered compilation is really useful on a device like a Raspberry Pi. The C1 gives startup and early runtime a great boost, and when C2 kicks in it gets even better. Waiting for C2 on everything puts a lot of early compilation pressure on the runtime and interpreter performance is very bad before hitting compilation thresholds.

aahlenst commented 3 years ago

I ran the jtreg tests (JDK 16, test/hotspot/jtreg/compiler/tiered/) for tiered compilation on the Raspberry Pi 4 and they succeeded. They enable tiered compilation and LevelTransitionTest.java shows that it compiles up to level 4. So I'd say that although tiered compilation is disabled by default it should work.

I did some more experiments, all with TieredCompilation enabled. I got Minecraft to start repeatedly with 1G RAM. With 512M, it sometimes succeeded and sometimes failed. Considering jstack is reporting a deadlock (which is consistent with the observation that the program does not proceed anymore), I think it makes sense to turn the attention towards Minecraft. Maybe there has been some deadlock sleeping all along, which is now being triggered by some combination of low memory and changes to the JDK.

jocull commented 3 years ago

Hmmm did those tests pass running on 32bit or 64bit?

I did just get a Pi 4 B, and it runs Minecraft just fine with tiered. Oddly tiered compilation is on by default for aarch64, at least on the 64bit versions distributed by Ubuntu. I haven’t yet tried an AdoptOpenJDK flavor on the Pi 4 B yet.

aahlenst commented 3 years ago

My Pis are all still in 32 bit mode with a 32 bit OS and JDK.

jocull commented 3 years ago

I think we can close this one. There must just be some differences in the platform (or a bug in Minecraft!) that aren’t well understood. Thanks for the assistance!