Java 8: Extrem hohe CPU Last wegen -XX:ReservedCodeCacheSize

Gestern hatte ich wieder einmal einen «Aha»-Moment. Wir haben eine Java-Applikation von Java 1.7.0_45 auf Java 1.8.0_71 angehoben, mit allen Schweinereien drumherum (neuster Weblogic 12.2.1, neuste DB2 JDBC Treiber, neuster Application-Release, usw).

Die CPU Usage ging nach dem Change während der Regelarbeitszeit ins unermessliche: Load Average von über 30-50 bei 8 vCores und ohne IOWait – obwohl die Anwender nicht mehr Arbeiteten und auch der etwas veränderte Application Code als unmöglich die Ursache bezeichnet wurde.

-XX:ReservedCodeCacheSize war zu niedrig

Das wichtigste zuerst: Die Ursache war die Java Start Option -XX:ReservedCodeCacheSize=96M, die damals schon mit JDK 7 eingepflegt wurde. JDK7 brachte hier einen Default Wert von 48M, den man damals auf 96M verdoppelt hatte. JDK 8 hingegen bringt für diese Option einen viel höheren Standardwert von 256M mit. Solange der Wert in unserer Umgebung auf 96M gesetzt war, reichte der Cache augenscheinlich nicht aus.

Welcher Thread verbrennt meine CPU?

Bis heute war es mir schnuppe zu wissen, wie ich die Java-Threads mit der höchsten CPU-Last sehen kann. Nun habe ich es zwangsweise gelernt und es ist an sich überhaupt nicht schwer, obwohl ohne extra-Tools etwas fummelige Arbeit. So geht’s:

1. Top mit SHIFT-H auf Thread-Ansicht umschalten
   1. C drücken um Java-Options zu sehen
   2. Bei Bedarf mit SHIFT-O und „m“ die Anordnung nach „CPUTime“ auflisten
2. Die Nummer in der PID-Spalte nach HEXadezimal umrechnen ( Zb. Mit diesem Web-Tool )
3. kill -3 auf die echte JVM-PID > das schreibt nur einen Thread-Dump ins Stdout Log und killt nichts effektiv.
4. Im Thread-Dump nach der HEXadezimal Zahl suchen > Der entsprechende CPU-lastige Thread wird angezeigt.

In diesem Fallbeispiel waren die Threads mit der höchsten CPU Last reine Compile Threads, alle diese Threads verbrannten sehr oft ein Core zu 100%.

### Thread Dump - Threads mit der höchsten CPU-Last

"C2 CompilerThread0" #8 daemon prio=9 os_prio=0 tid=0x00007f243db8b800 nid=0x6e91 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #9 daemon prio=9 os_prio=0 tid=0x00007f243db91000 nid=0x6e92 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"C2 CompilerThread2" #10 daemon prio=9 os_prio=0 tid=0x00007f243db94000 nid=0x6e93 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"C1 CompilerThread3" #11 daemon prio=9 os_prio=0 tid=0x00007f243db95000 nid=0x6e94 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

Bei JDK8 lohnen sich die Default Werte viel mehr als noch bei JDK7. Daher meine Empfehlung: Während jeder Migration auf JDK8/9 sollten die früher gesetzten Wert genau unter die Lupe genommen werden, sonst passiert es wie in diesem Fall, eine nervige Verschlimmbesserung…