Continuous Monitoring with JDK Flight Recorder

Article from JAVA Magazine 2021 – 04

Waarom dit artikel?

Vreemd genoeg is het profilen van de JVM of een specifiek proces niet één van de taken in een standaard sprint. Redenen daarvoor kunnen zijn dat er een dure licentie voor nodig is, dat ontwikkelteams nog niet heel bekend zijn met de goede tools die er rondzwerven op het internet en/of waarvan de learning curve te groot is om het even in een sprint erbij te doen.

 

De tools die ik tijdens het ontwikkelen voorbij heb zien komen, zijn de commerciële JProfiler, YourKit, IBM MAT en de niet commerciële Netbeans Profiler en VisualVM.
VisualVM lijkt het vaakst gebruikt te worden, wellicht omdat deze met Oracles JDK 6~8 werd gedistribueerd. Nog erger, en helaas nog vaker tegengekomen dan de vorige genoemde tools, de klassieke:

 

long start = System.currentTimeMillis();
//…
long finish = System.currentTimeMillis();

long timeElapsed = finish – start;

 

De al wat hippere ‘StopWatch’ oplossing van Apache Commons Lang, omdat we die library toch al negen van de tien keer op ons classpath hebben staan.

 

StopWatch watch = new StopWatch();

watch.start();

// CODE HERE

watch.stop();

System.out.println(“Time Elapsed: ” + watch.getTime());  // Prints: Time Elapsed: 2501

 

Laten we eerlijk zijn, hiervoor geldt natuurlijk: iets is beter dan niets! Buiten de performance overhead en dat het je niks meer gaat vertellen dan dat iets er een bepaalde tijd over heeft gedaan, maar niet waarom het er zo lang over heeft gedaan.

 

Beeld je in dat er een productie incident is en jij staat ‘standby’. Precies op die ene module die je nog nooit hebt hoeven aanraken en waarvan gegarandeerd wordt dat er nooit iets mis mee is. Waarschijnlijk ook nog op een tijdstip waarop je zelden wakker bent. Het is uiteraard op een applicatie die cruciaal is en 24/7 in de lucht moet zijn. Het enige wat je hebt is een error melding of het systeem is vele malen trager dan normaal. Wat doe je dan meestal? Je kijkt naar de data die beschikbaar is. Uit de logging en de data kan je helaas niks halen, of alleen afleiden dat het inderdaad trager is dan normaal.

 

Omdat je niet de juiste informatie hebt, voeg je extra logging toe, zodat je méér informatie hebt als dit probleem de volgende keer optreedt. En dan wachten… Je zal zien dat dit voorlopig niet meer optreedt, maar je logging nu op een cruciale plek staat en eigenlijk alleen maar voor vertraging zorgt. Dus er komt een moment dat je de keuze moet maken: ga ik deze code weer weghalen of ga ik de logging uitzetten? Meestal zie je dan dat deze uitgezet wordt.

 

 

 

{ Maar wat dan wel? }

Java heeft hier al wat voor bedacht en gemaakt, namelijk de Java Flight Recorder(JFR) met Java Mission Control (JMC). JMC is een soort van ‘Swiss Army Knife’ (zo een die MacGyver altijd bij zich had). Het integreert:

 

  • jmap (Java memory map)
  • jstack (stacktraces)
  • jinfo (JVM configuration info)
  • jstat (JVM statistics)
  • jconsole/JMXConsole (JMX beans)
  • JVM browser
  • Java Flight Recorder GUI

 

Als je JDK 7u40 of hoger gebruikt, wordt JMC meegeleverd in je bin directory. Vanaf openJDK 11 en hoger kan het zijn dat JMC niet meer meegeleverd wordt, maar deze kan dan wel nog los worden gedownload en geïnstalleerd.

 

De commandline tools die in cursief staan gemarkeerd kunnen bekend voorkomen. Deze worden al een tijdje meegeleverd met JDK versies. Oracle adviseert om het nieuwste hulpprogramma ‘jcmd’ te gebruiken in plaats van de vorige hulpprogramma’s ‘jstack’, ‘jinfo’ en ‘jmap’. Dit voor verbeterde diagnostiek en verminderde performance overhead.

 

JMX console maakt real-time monitoring mogelijk. Het verbindt via JMX naar een al draaiende JVM en toont real-time statistieken, zoals thread informatie of geheugen en CPU gebruik.

 

JMC is dus ook een visuele weergave van de opgenomen flight recording. Het heeft zelfs een ‘Automated Analysis Results’ pagina, zie afbeelding 1. De pagina extraheert en analyseert de gegevens uit de flight recordings en helpt bij het identificeren van overduidelijke problemen.

 

Afbeelding 1.

 

{ Oké, maar wat is JFR dan? }

JFR is een tool voor het verzamelen van diagnostische en profile gegevens over een actieve Java-applicatie. Het is een ‘event based tracing framework’ dat geïntegreerd is in de Java Virtual Machine (JVM) die bijna geen performance overhead veroorzaakt. Het kan dus zelfs in zwaar belaste productieomgevingen worden gebruikt. JFR komt standaard met twee profielen, namelijk ‘default’ en ‘profile’. Wanneer de default profile wordt gebruikt, is de impact op de prestaties minder dan één procent. Het profile profiel heeft ongeveer 2% overhead.

 

Je kan ook je eigen profielen maken, dit zijn XML files die opgeslagen worden in /lib/jfr/*.jfc. Voor sommige toepassingen kan het aanzienlijk lager zijn, maar voor kortlopende applicaties kunnen de relatieve opstart- en opwarmtijden echter langer zijn, wat de prestaties met meer dan één procent kan beïnvloeden. JFR verzamelt gegevens over de JVM én de Java-applicatie die erop wordt uitgevoerd. Een extra gave feature is dat je de flight recorder ook alsnog op een al draaiend proces kan activeren.

 

Laten we deze vorm van profiling eens tegen de al eerder besproken log statements aanhouden (afbeelding 2).

 

Afbeelding 2.

 

Deze statistieken zijn geleend van Oracle zelf en het verklaart waarom Oracle ook promoot om JFR (continu) in productie te gebruiken. Op de verticale as zie je de kosten uitgedrukt en op de horizontale as de profiling oplossingen. Hoe is het mogelijk dat ‘JFR disabled’ geen kosten heeft? Dit is vanwege Java’s JIT compilatie (Just-in-timecompilatie). ‘Log4j off’ komt qua kosten niet slecht uit de verf, maar kijk eens naar het verschil tussen ‘JFR enabled’ en ‘Log4j on’. Indrukwekkend is dat ‘JFR on’ minder kost dan ‘Java util logging off’. De reden dat de laatste twee logging frameworks niet zijn ingetekend is, omdat deze alle andere kolommen compleet doet wegdrukken.

 

Afbeelding 3.

 

{ < 1 %… Hoe dan? }

Java gebruikt intern al events om de JVM draaiende te kunnen houden, aan de hand van die events bepaalt de JVM bijvoorbeeld:

  • Welke methode moeten we JIT (Just-in Time) compileren.
  • De garbage collector (GC) neemt ook beslissingen aan de hand van deze events.

 

De JVM heeft al die detailinformatie dus sowieso al. Het enige wat Java nu met JFR heeft gedaan, is deze op een hele efficiënte manier beschikbaar maken voor ons. Dit zodat wij precies kunnen zien wat er nu in de JVM en dus ook in onze applicatie allemaal gebeurt.
Wat ze nu ook beschikbaar hebben gemaakt, is dat je zelf dit soort events kan produceren. Dus niet alleen de JVM, maar ook jouw applicatie kan events produceren. Als je op zo’n low-level niveau events gaat analyseren, dan kan het gaan om grote hoeveelheden. Vandaar dat JFR wordt geleverd met een filtering mechanisme. De uiteindelijk kracht zit ‘m dan ook in het correleren van deze events (Applicatie, Java Runtime libs, JVM, OS).

 

{ Events filteren en correleren }

Events kunnen gefilterd worden op type/naam en doorlooptijd. Als je dus niet geïnteresseerd bent in ‘Class loading events’, dan kan je deze wegfilteren. Zelf vind ik het filteren op de doorlooptijd van events heel handig. In events met een korte doorlooptijd zijn we waarschijnlijk niet geïnteresseerd, maar wanneer die langer duurt dan 200ms juist weer wel.

 

Wat gebeurde er tijdens dat event in de JVM? Zat de tijd in een database, was de garbage collector druk bezig of was het OS op dat moment druk? In de meeste gevallen begin je high-level en ga je steeds dieper tot je bij je probleem uitkomt.

 

{ Eigen JFR events maken }

Is mogelijk sinds Java 9 en is niet moeilijker dan:

 

import jdk.jfr.Event;

public class RestCallEvent extends Event {

public String path;

}

 

{ Recordings maken }

Dit kan op 2 manieren via een GUI met JMC en via de commandline met jcmd (en JMX).
Bij het maken van een recording maak je een keuze voor:

 

  • Een tijdsgebonden periode.
    • Record voor een specifieke tijd.
    • Schrijft naar een bestand wanneer klaar of opent automatisch in JMC GUI.

 

-XX:StartFlightRecording=delay=20s,duration=60s,filename=C:\myrec.jfr,settings=profile,name=MyRecording

 

    • Record totdat de JVM stopt of wordt gestopt.
    • Schrijft naar een bestand wanneer verzocht of wanneer ingesteld als de JVM stopt en als ingestelde triggers afgaan, zoals Exceptions of CPU load. Triggers instellen is nu alleen nog maar mogelijk via JMC.

 

-XX:StartFlightRecording=settings=default, dumponexit=true,  filename=/var/jfr/dumps

 

Starten van een recording “jcmd  <pid> <command>”:

 

jcmd 7060 JFR.start name=MyRec settings=profile delay=20s duration=2m filename=/var/jfr/myRecording.jfr

 

Wegschrijven van een recording:

 

jcmd 7060 JFR.dump filename=/var/jfr/dump.jfr

 

{ Conclusie }

Na het lezen van dit artikel kun je dus gelijk aan de slag met het analyseren en oplossen van je software die nu in productie staat zonder daar iets voor te installeren. Niet meer het internet afstruinen naar profiling tools, want deze wacht al sinds Java 7u40 (2013) in je java/bin folder. Dumps maken in productie in het heetst van de strijd en op een later tijdstip op je gemak analyseren met je team. Sinds Java 11 is JFR open source geworden en zal de JVM een ‘warning’ geven wanneer het argument XX:+UnlockCommercialFeatures wordt meegegeven. Versies voor Java 11 moeten nog wel features activeren via:

 

XX:+UnlockCommercialFeatures -XX:+FlightRecorder

 

BIO

Rick Roelofsen is Senior (Lead) Developer bij GROUP9 en competence manager van bright-r. Kennis delen met de toekomst geeft hem kracht en energie.