Slow application, frequent JVM hangs with single-CPU setups and Java 12+

From my experience performance problems with JDKs are related mostly to one of the following:

  • JIT Compilation
  • VM configuration (heap sizes)
  • GC algorithm
  • Changes in the JVM/JDK which break known good running applications
  • (Oh, and I forgot to mention class loading...)

If you just use the default JVM configuration since OpenJDK11, maybe you should set some of the more prominent options to fixed values, like GC, Heap size, etc.

Maybe some graphical analyse tool could help track your issue down. Like Retrace, AppDynamics or FlightRecorder and the like. These give more overview on the overall state of heap, GC cycles, RAM, threads, CPU load and so on at a given time than log files could provide.

Do I understand correctly that your application writes about 30710 lines to the log within the first second of running (under OpenJDK11)? Why is it "only" writing about 7k lines under OpenJDK14 in the first second? This seems like a huge difference for an application that is just started on different JVMs to me... Are you sure there are not for example high amounts of Exception stacktraces dumped into the log?

The other numbers are even higher sometimes, so maybe the slowdowns are related to exception logging? Or even swapping, if RAM gets low?

Actually I am thinking, if an application does not write anything into the log, this is a sign of smooth running without problems (unless it is frozen entirely in this time). What is happening from seconds 12-22 (in the OpenJDK14 case here) is what would concern me more... the logged lines go through the roof... why?

And afterwards the logging goes down to all time low values of about 1-2k lines... what is the reason for that?? (Well, maybe it is the GC kicking in at second 22 and does a tabula rasa which resolves some things...?)

Another thing may be your statement about "single CPU" machines. Does this imply "single core" also (Idk, maybe your software is tailored on legacy hardware or something)?

And the "single CPU" VMs are running on those machines? But I assume, I am wrong about these assumptions, since almost all CPUs are multicore nowadays... but I would investigate on a multithreading issue (deadlock) problem maybe.


Since it's using 100% CPU "most of the time", and it takes 10 times longer (!) with Java 14, it means that you're wasting 90% of your CPU in Java 14.

Running out of heap space can do that, as you spend a whole lot of time in GC, but you seem to have ruled that out.

I notice that you're tweaking the biased locking option, and that it makes a significant difference. That tells me that maybe your program does a lot of concurrent work in multiple threads. It's possible that your program has a concurrency bug that shows up in Java 14, but not in Java 10. That could also explain why adding another CPU makes it more than twice as fast.

Concurrency bugs often only show up when you're unlucky, and the trigger could really have been anything, like a change to hashmap organization, etc.

First, if it's feasible, check for any loops that might be busy-waiting instead of sleeping.

Then, run a profiler in sampling mode (jvisualvm will do) and look for methods that are taking a much larger % of total time than they should. Since your performance is off by a factor of 10, any problems in there should really jump out.


TL;DR: It's an OpenJDK regression filed as JDK-8244340 and has been fixed in JDK 15 Build 24 (2020/5/20).

I did not except that but I could reproduce the issue with a simple hello world:

public class Main {
    public static void main(String[] args) {
        System.out.println("Hello world");
    }
}

I have used these two batch files:

main-1cpu.bat, which limits the java process to only one CPU:

c:\windows\system32\cmd.exe /C start /affinity 1 \
    \jdk-14\bin\java \
    -Xlog:all=trace:file=app-1cpu.txt:uptime,tid,level,tags:filecount=50 \
    Main

main-full.bat, the java process can use both CPUs:

c:\windows\system32\cmd.exe /C start /affinity FF \
    \jdk-14\bin\java \
    -Xlog:all=trace:file=app-full.txt:uptime,tid,level,tags:filecount=50 \
    Main

(The differences are the affinity value and name of the log file. I've wrapped it for easier reading but wrapping with \ probably doesn't work on Windows.)

A few measurements on Windows 10 x64 in VirtualBox (with two CPUs):

PS Z:\main> Measure-Command { .\main-1cpu.bat }

...    
TotalSeconds      : 7.0203455
...


PS Z:\main> Measure-Command { .\main-full.bat }

...
TotalSeconds      : 1.5751352
...


PS Z:\main> Measure-Command { .\main-full.bat }

...
TotalSeconds      : 1.5585384
...


PS Z:\main> Measure-Command { .\main-1cpu.bat }

...
TotalSeconds      : 23.6482685
...

The produced tracelogs contain similar pauses that you can see in the question.

Running Main without tracelogs is faster but the difference still can be seen between the single-CPU and two-CPU version: ~4-7 seconds vs. ~400 ms.

I've sent this findings to the hotspot-dev@openjdk mail list and devs there confirmed that this is something that the JDK could handle better. You can find supposed fixes in the thread too. Another thread about the regression on hotspot-runtime-dev@. JIRA issue for the fix: JDK-8244340

Tags:

Java

Freeze

Java 14

Recent Posts