With the Hotspot JDK 7u40 there is a nifty new tool called Java Mission Control. Users of the nifty old tool JRockit Mission Control will recognize a lot of the features. This particular blog entry focuses on the Java Flight Recorder and various ways you can go about to create a flight recording.
In the last blog entry about the method profiler I showed that Mission Control can be quite useful for profiling production systems. However, I only showed one way to produce the actual recording.
There are several different ways to produce a recording, all of them useful in a certain context. But before we get into that, we should first discuss the two different kinds of recordings.
Continuous Recordings
Continuous recordings are not only very hard to spell, they are also very common in production systems. Well, if Java Flight Recorder will be used anything like the JRockit equivalent, at least they will be. Continuous recordings have no end time and will keep recording until the JVM shuts down, or someone tells it to end. This kind of recording can be dumped at any point in time when access to the data being recorded is needed.
Time Fixed Recordings
Also known as profiling recordings, these recordings run for a fixed amount of time and then automatically end themselves. These typically use templates that enable costlier events, since the performance penalty will only be suffered for a limited duration of time.
Note that it is perfectly feasible to have several recordings running in parallel. It is even quite common. Which brings me to the first quirkiness of the Java Flight Recorder: Recordings active at the same time share the same buffers!
It may be easier to consider recordings to be named sets of Event Type settings, i.e. settings of what to record, that are being pushed and popped from the recording engine. At any given time, the union of the settings dictates what will be recorded.
Here is an example:
A continuous recording R0 is started at T0 with settings S0. After a while, a time fixed recording R1 is started at T1 with settings S1, where S1 ⊃ S0. The time fixed recording R1 ends at T2. This is what will be recorded:
Time | Settings |
---|---|
T0→T1 | S0 |
T1→T2 | S0 ∪ S1 |
>T2 | S0 |
Note that this means that if you dump the continuous recording R0 for a time range intersecting [T1,T2], you will actually find that you are getting information in your “recording” that you did not ask for in the settings (S0). All this in the name of performance. Once T2 arrives, the settings for R1 will be popped, and we’re back to just recording S0.
Now, one last reminder before getting back to the actual recording:
The 1st Rule of Flight Recording* |
---|
Thou Shalt Never Forget to Start Your JVM with -XX:+UnlockCommercialFeatures -XX:+FlightRecorder |
RAmen!
(* Only required in HotSpot. With JRockit, no command line flags are required.)
Creating a Recording from Within Mission Control
This is probably the easiest way to produce a recording, since you get help both with connecting to the JVM from which you want the recording, and a nice wizard that helps you to select what to record. I went through the recording wizard in the blog entry about the method profiler, so I will not repeat that here. I will just note that the template settings that you arrive at can be exported from Mission Control, and then stored server side so that anyone connecting to that JVM though Mission Control will have access to it. Simply create a recording with the settings you would like to store, next go to the Template Manager, select the template marked as “ – last saved” and hit Export. Then put the exported file in the jre/lib/jfr folder of the JVM where you want to make the template available.
Creating a Recording Using Command Line Arguments
This is quite useful when you want to record the start up behaviour of an application, or when you want to make sure that your application always starts with a continuous recording running. Since I am a staunch believer of examples, I’ll simply give three examples.
Here is an example of how to start a one minute time fixed recording, 20 seconds after the JVM has started, using the profile template :
-XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:StartFlightRecording=delay=20s,duration=60s,name=MyRecording,filename=C:\demo\myrecording.jfr,settings=profile
Note that the settings parameter either takes a path to a template, or the name of a template which must be available in the jre/lib/jfr folder of the JVM.
Here is an example on how to start a continuous recording, using the default template:
-XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:StartFlightRecording=name=MyRecording,settings=default
Note that in the second example we do not specify any file name. The data will need to be dumped on request, either using Mission Control or jcmd, or possibly by using the dump-on-exit parameters to make the JVM dump the recording when exiting the JVM, like this:
-XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:FlightRecorderOptions=defaultrecording=true,dumponexit=true,dumponexitpath=c:\demo\dumponexit.jfr
For more information on the available parameters, see the Java Command Line Reference.
Creating a Recording Using JCMD
You can also control the Flight Recorder even after you have started the java process (as long as you adhere to the 1st Rule of Flight Recording) using JCMD. The JCMD utility is in the JAVA_HOME/bin folder and allows you to enumerate the locally running Java processes, and send commands to them. Just running jcmd will list the running Java processes and their PIDs:
C:\Java\jmc5.2labs>jcmd
4711 LoadAndDeadlock
1276 sun.tools.jcmd.JCmd
To query a certain JVM for the available commands, use “help”:
C:\Java\jmc5.2labs>jcmd 7484 help
7484:
The following commands are available:
JFR.stop
JFR.start
JFR.dump
JFR.check
VM.native_memory
VM.commercial_features
ManagementAgent.stop
ManagementAgent.start_local
ManagementAgent.start
Thread.print
GC.class_histogram
GC.heap_dump
GC.run_finalization
GC.run
VM.uptime
VM.flags
VM.system_properties
VM.command_line
VM.version
help
For more information about a specific command use 'help <command>'.
Here is an example which starts a continuous recording from the command line using JCMD (assuming that the PID of the Java process you want to record on is 4711):
C:\Java\jmc5.2labs>jcmd 7484 JFR.start name=MyRecording settings=default
4711: Started recording 1. No limit (duration/maxsize/maxage) in use.
Use JFR.dump name=MyRecording filename=FILEPATH to copy recording data to file.
The JFR.check command can be used to check the status of the recordings:
C:\Java\jmc5.2labs>jcmd 4711 JFR.check
4711:
Recording: recording=1 name="MyRecording" (running)
To dump the recording:
C:\Java\jmc5.2labs>jcmd 4711 JFR.dump name=MyRecording filename=C:\demo\jcmddump .jfr
4711:
Dumped recording "MyRecording", 180.3 MB written to:
C:\demo\jcmddump.jfr
Then you can just drag and drop the resulting file into Mission Control to view the contents:
(No blog post is complete without a Pretty Picture™.)
Further reading and useful links
Related Blogs:
Java Mission Control Finally Released
My JavaOne 2013 Sessions
Low Overhead Method Profiling with Mission Control
The Mission Control home page:
http://oracle.com/missioncontrol
Mission Control Base update site for Eclipse:
http://download.oracle.com/technology/products/missioncontrol/updatesites/base/5.2.0/eclipse/
Mission Control Experimental update site (Mission Control plug-ins):
http://download.oracle.com/technology/products/missioncontrol/updatesites/experimental/5.2.0/eclipse/
The Mission Control Facebook Community Page (not kidding):
http://www.facebook.com/pages/Java-Mission-Control/275169442493206
Mission Control on Twitter:
@javamissionctrl
Me on Twitter:
@hirt
Markus, thank you for your great work on JFR and useful posts popularizing Flight Recordings.
We are all waiting for you at JavaOne 2014 in Russia and new edition of your book “Oracle JRockit: The Definitive Guide”!
Thanks Mike! I don’t think there will be a new edition of Oracle JRockit: The Definitive Guide, but there might be something else on the way. 😉
Hi,
Thanks for your great postings about using Hotspot together with JMC! I have one remark. I think there are some options missing in your example where you outline how to make the JVM dump a contiuous recording when exiting. I have to use at least the following options:
-XX:+UnlockCommercialFeatures
-XX:+FlightRecorder
-XX:StartFlightRecording=name=default,settings=default
-XX:FlightRecorderOptions=dumponexit=true,dumponexitpath=C:\jmc\finished\dump.jfr,defaultrecording=true,disk=true,repository=C:\jmc\temp\
Best regards,
Bill
Quite true Bill! The defaultrecording parameter must be set!
This looks fantastic!
Where could I get some information about how to start a session on-demand? (instead of all the boot-time arguments or with the jcmd command-line tool)
We have a javaagent that monitors JVMs and I’m wondering if, assuming we could talk to this agent in some fashion, we could tell it “start now, run for 60 seconds,…, dump the output to /tmp/foo.jfr”?
Also, is there any information about how to parse and interpret the eventual dump with the collected info?
Thank you!
Hi Otis!
In JDK 8 there is an MBean allowing you to execute diagnostic (jcmd) commands. I’ll write a blog on using it once JDK 8 is out. There is currently no supported way to parse recordings, but I may write a blog on how to use the Mission Control parser to do it (after JavaOne, too busy now).
Kind regards,
Marcus
Hello Marcus,
I want to profile a program which takes some time to run (approx. 24h). I have already enabled continuous recordings successfully. The recordings are written to disk. The JVM start-up parameters which I use are outlined in my previous post (Friday, September 13, 2013).
The problem is, that the recording only contains data from approx. the last three hours of the program run. Is there something like a -maxRecordingDuration for the Java Flight Recorder?
Kind regards,
Bill
Yep, but I don’t recall it defaulting to anything other than unlimited. There is also a size limit that can be set, but again I don’t think it’s set to anything other than unlimited by default. Please ask in the official JMC forum, and I’m sure that someone will help. (And if no one bites, I promise to take a look myself.)
Hello Marcus,
I found a solution for my problem posted on September 30, 2013 at 11:00.
The documentation says that {{{maxage}}} and {{{maxsize}}} default to values which result in unlimited continuous recordings. This is not true. You have to set this parameters explicitely. Otherwise the recordings contain only data for the last few hours. This is true as of Java 7u40.
What are the license implications of using “-XX:+UnlockCommercialFeatures” in the JDK ? Any docs/links ?
You may not use commercial features in production without obtaining a license from Oracle.
http://www.oracle.com/technetwork/java/javase/terms/license/index.html
(Disclaimer: I’m a techie so you should probably ask someone else.)
Kind regards,
Marcus
Great that you found a solution! Not so great that the docs aren’t up to date. I will forward this information (i.e. create a bug report).
Kind regards,
Marcus
Hi Marcus, I went through some of your recordings. Being very new to performance monitoring and handling JRMC initially is a pretty big deal, but interesting nonetheless. The question I wanted to ask is that, what options and MBeans related to the JRockit JVM can I change during Runtime (during a flight recording), other than just GC strategies and heap size. I’ve been exploring but can’t quite come up with more. Appreciate your help.
-Zim
Thank you for your useful article.
When I finished flight recording I can not open file. The problem is :
Could not load events from flight_recording_2013-12-11_11_15_09.jfr
java.lang.IllegalArgumentException: com.sun.org.apache.bcel.internal.generic.ClassGenException: Illegal opcode detected.
What may be my problem?
Not sure. I haven’t seen that before. Can you send me the recording?
Kind regards,
Marcus
Hi Zim,
JRockit is no longer in active development. That said, on the MBean API side of things, there are some interesting things you could do with JRockit (such as changing GC strategy dynamically and changing the target heap size), that you cannot do with HotSpot. And yes, there are a few other things, such as counting method invocations and seeing method invocation times on a per method basis. Also, the on-line Memleak Analysis Tool that was available for JRockit is not yet available for HotSpot. That said, HotSpot is our base platform going forward. If you want to check on our progress with the convergence between the JRockit and HotSpot platforms, download 7u40 and have a look at Java Mission Control.
Also, just wanted to point out that the Flight Recorder and the JMX Console are two different things. If you haven’t played with the Flight Recorder yet, you’re in for a treat. 🙂
Kind regards,
Marcus
Hi Marcus;
My record file is there : https://drive.google.com/folderview?id=0ByhJGUfO_djHNm9YMnZOWDZVWGM&usp=sharing
Thak you so much,
Metin
Hi Metin,
Your file opens just fine for me. Which version of the JMC client are you trying to use to open the file?
Kind regards,
Marcus
Hi
Does this feature work in OpenJDK Hotspot VM? I seem to be getting unrecognized vm option error for -XX:+UnlockCommercialFeatures
The Java Flight Recorder features requires the Oracle JDK.
got the same problem as metin.
Could not load events from my_flight{record_file_path.jfr
com.jrockit.mc.flightrecorder.internal.parser.binary.InvalidFlrFileException
Hi Markus,
thanks for all your work. I have a question regarding a lot of Methods which are shown as “Unknown” in the Call Tree View. I am a beginner in Profiling and have no clue what could be an explanation.
I found a setence in the JFR Runtime Guide which could be connected but I don’t understand it fully:
“In some cases, the JVM drops the event order to ensure that it does not crash. Any data that cannot be written fast enough to disk is discarded.” Is there somewhere a further explanation on that?
Here a picture of my profiling file:
http://www.directupload.net/file/d/3830/7a8cf6cc_png.htm
Hi Sebastian,
If the pressure on the recording engine is too high, it will prefer dropping data to halt the runtime. This is for performance reasons. That said, I’ve never seen this happening in a real life recording. Also, JFR will emit special buffer lost events to indicate that data was lost, so you should be able to see this in your recording.
Also, for your unknown methods, did you try this: http://hirt.se/blog/?p=609
Kind regards,
Marcus
Hi Markus,
thanks for your fast reply! In my JFR-File I don’t see any buffer lost events. (Where and how would I see them?)
I used the following parameters: -XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints -XX:FlightRecorderOptions=defaultrecording=true,dumponexit=true,dumponexitpath=javaFlightRecording.jfr
I started the recording the same program again without changing anything and I got a totally different picture. But still there are a few unclassifiable and unknown methods. Here is a picture:
http://www.directupload.net/file/d/3831/xs7eqev4_png.htm
Is there anything I can do about it?
Furthermore, I recognized that the total Sample Count is around 400 in 8 minutes. In a simple program (calculating Fibonacci numbers recursivly) for testing JFR I wrote, I got a Sample Count of around 500 in only 18 seconds. This makes me wonder, since I thought the Samples are like cuts through the JVM in always the same pulse. I expected that an 8 minute recording must have considerably more Samples than an 18 second recording.
Do you have an explanation for me? Thanks in advance!
Hi Sebastian,
If you have very little load on your machine, there will be very few samples. The method profiler is sampling threads busy doing something, i.e. contributing to the load of the machine. Halted threads will not contribute. If you do not have high CPU saturation caused by the JVM process, the method profiling information is of less interest.
Which exact version are you running on? There was a bug introduced in JDK 7u60 (https://bugs.openjdk.java.net/browse/JDK-8038497), which is resolved in JDK 7u80.
Kind regards,
Marcus
Hi Marcus (sorry for the previous spelling mistakes in your name -.-),
I am running on version 1.7.0_71-b14 locally (Win7) and on the Jenkins server (Linux) where I also integrated JFR I am running on 1.7.0_65-b33.
What effect does the bug you posted have on the samples? Unfortunately the description to the bug is missing. Is this bug limited to the OpenJDK or does it affect the OracleJDK as well? (There is a difference I thought…)
Furthermore, I have seen that there is a bug which shall lead to fewer samples which is referenced to here: https://community.oracle.com/thread/2579717 (Q: Why do I get a lot fewer method samples then I expected?) Is this the same bug you have been talking about?
Thanks in advance!
IIRC there are two bugs. One can give you less samples than you would expect, and one can give you a timestamp offset between event types using different ways of retrieving timestamps. As far as I can tell, the former should be fixed in 7u60, and the latter in 7u80. If you have a high JVM process load, you should get enough sample points.
Hi Markus,
once again I have a question regarding the Method Samples. Is there a possibility to change the Method Sampling interval to below 10 ms?
In the “Flight Recording Template Manager” of JMC I can choose three levels of Method Sampling: Off, Normal and Maximum, where Maximum is connected to the value “10 ms” in the Template-XML-File.
999 d
20 ms
10 ms
…
true
10 ms
When I manually change this value 10 ms – either through the GUI in the “Advanced” window of the Flight Recording Template Manager or directly in the template-XML-File – I see the following behaviour:
A value above 10 ms works as expected. The sum of the samples went down.
With a value below 10 ms the Flight Recorder does not record anything anymore. The created dump file is of the size 30 kb and when I open it with JMC I get the message “This Flight Recording has no Recording Settings events.”.
I turned off the other options in the Template-File (Garbage Collector, Compiler, Thread Dump and Exceptions). The JVM-Parameter I used are the following: -XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints -XX:StartFlightRecording=settings=$WORKSPACE/jfrSettings.jfc,defaultrecording=true -XX:FlightRecorderOptions=dumponexit=true,stackdepth=512,dumponexitpath=$WORKSPACE/reports/
Thanks for your help!
Hi Sebastian,
Which version were you running?
Kind regards,
Marcus
A member of the serviceability team said the current implementation has a limit at 10ms. Seems there is a limit in the OS timer task they are currently using.
Thank you so much for this documentation. I am running a POJO java application on Linux and was unable to connect to Flight Recorder on my PC. The “Creating a Recording Using Command Line Arguments” section allowed me to profile the app. Need to process 50 million records in less than an hour and had a performance issue that was not scaling. No matter how many threads the performance did not improve due to blocking by PrintStream (System.err.println). You saved me! Now that we know the problem there are several easy solutions to fix it and restore the scalability of this app.
Glad we could help! 🙂
/M
Hi Marcus,
While trying to record a session using Flight recorder, i am experiencing a error related to loading of SAXParserFactory
Provider com.ebay.raptor.xmlfactorywrapper.SAXParserFactoryWrapper not found
But i was able to connect to JMX console and able to gather all JVM metrics
Platform :
JDK used in client side 1.8 update 60 on windows 7
Server Side JDK 1.7 update 40 on Redhat 5.2 linux platform
Tomct Servlet Container
Tried adding this system parameter to the JVM options
Djavax.xml.parsers.SAXParserFactory=com.sun.org.apache.xerces.internal.jaxp.SAXParserFactoryImpl
But still the same error
Could you please review and let me know how we can handle this
Thanks
sattish.
Hmmm. -Djavax.xml.parsers.SAXParserFactory=com.sun.org.apache.xerces.internal.jaxp.SAXParserFactoryImpl should do the trick. Check your recording to verify that the system property really was set.
Hi Marcus,
I tried by setting this property option in JVM arguments but still the same but things worked well when i used Java 1.7 update 45. Not sure whats the difference between 1.7.0_45 with 1.8.0_60
Thanks
sattish.
Hi Marcus, would it be possible to make the “filename” argument to JFR.dump optional, and have the recording output to stdout if “filename” was missing? We are profiling a Java application that is running inside a Docker container, and would like to avoid having to store the recording inside the container.
Thanks for any insight you may have.
Regards,
Jan
Hi Everyone,
I have .jfr file which I want to open using command-line in windows/linux machine. I tried it by giving command e.g. d:\JRMC\bin>jrmc ABC.jfr
But using this command JRMC application opened but my jfr file “ABC.jfr” is not got opened in JRMC.
Please let me know how to open jfr file using command line?
Thanks,
Manish
I don’t remember if this was the same in jrmc, but with jmc you can do jmc -open ABC.jfr.
Hi Marcus,
I enabled JFR today on my weblogic 12.2.1.2 (running on Linux) by adding the below parameter to setDomainEnv.sh file.
JAVA_PROPERTIES=”${JAVA_PROPERTIES} -XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:FlightRecorderOptions=repository=/u04/test/jfrlogs”
export JAVA_PROPERTIES
After restart I’m able to start the recording using jcmd JFR.start, however, the file is not getting created in the repository location that I have specified. Am I missing anything here? Can you please suggest.
jcmd 31039 JFR.start duration=30s filename=test_critical.jfr
31039:
Started recording 13. The result will be written to:
//test_critical.jfr
The repository location is used by jfr internally, for example when maxage or maxsize is used. It is not the folder where your files will be emitted when done. Have you tried specifying an absolute path for your filename?
Thanks Marcus for your reply.
Yes when I explicitly mention the file location, it creates the jrf file there. But I thought repository parameter helps me to set a default location for jfr file even when I run the record manually. Isn’t that the case?
The repository location is internal to the workings of JFR. It is where the JVM will keep data when chunks are emitted to disk.
Thank you Marcus for the clarification.
Hi Marcus,
I add JFR in java start up opts, and I define dumponexit, so will JFR dump all the data from the beginning when exit JVM?
Thanks,
Roy
Hi Roy,
That depends on how you’ve configured JFR. If you’ve configured JFR to go to disk and set the limits to suitable value (IMHO you should always have a reasonable limit that makes sense, either size or time or both) that covers the entire run, then yes, it normally would. See the JVM documentation for more information on the JVM flags.
Also, the JVM can crash so that the final copy of the information does not get dumped to a single file at the target destination. Luckily the files in the repository (normally in tmp) are all self contained JFR chunks, and can still be read and used.
Hi Marcus
In your comments to Roy, you mentioned
“Luckily the files in the repository (normally in tmp) are all self contained JFR chunks, and can still be read and used”
Are you referring to the part file JFR generates to the repository directory? if so how can the part files be read and used?
Thanks
Phil
Partially written chunks are harder to do much with, but not impossible. But a fully written chunk is in itself a little flight recording, and can be opened as such. The repository will normally contain such little .jfr files, one .part file (which is the currently worked upon chunk) and a zero sized placeholder .jfr file for when the .part file is completed.
We have been thrown at the deep end of investigating a sudden JVM termination (killed by a wrapper process), all we’ve left with is a part file of JFR, i.e. a chunk that didn’t get the chance to be fully written to jfr file. The part file seems to be in a binary format, it’s much appreciated if you could share some docs or online references regarding parsing part file of JFR if there’re any.
Thanks
Not easy to do much unless you have a full chunk. The metadata describing the binary contents are written towards the end of the chunk (at least for versions up to and including JDK 11), and without that metadata, the binary information cannot be parsed. You could perhaps manually use the metadata from a previous chunk, and try to patch up the part file, but that requires luck, trial and error, and quite likely running the parser in debug mode to figure out what to patch and where.
I got same problem with Metin as follows. I found that error due to operation system (for me MacOs) language is Turkish. When change OS language as English problem has been resolved.
java.lang.IllegalArgumentException: com.sun.org.apache.bcel.internal.generic.ClassGenException: Illegal opcode detected.