TD;DR: -Xlog:jfr+startup=error is your friend.

Ever wondered why JFR emits something like

[0.172s][info][jfr,startup] Started recording 1. No limit specified, using maxsize=250MB as default.
[0.172s][info][jfr,startup] 
[0.172s][info][jfr,startup] Use jcmd 29448 JFR.dump name=1 to copy recording data to file.

when starting the Flight Recorder with -XX:StartFlightRecorder? Even though the default logging level is warning, not info?

This is what this week’s blog post is all about. After I showed you last week how to waste CPU like a Professional, this week I’ll show you how to silence JFR. Back to the problem:

The Answer lies in the Code

Let’s have a look at the OpenJDK source code:

if (startup) {
  if (log_is_enabled(Warning, jfr, startup))  {
    // if warning is set, assume user hasn't configured log level
    // Log to Info and reset to Warning. This way user can disable
    // default output by setting -Xlog:jfr+startup=error/off
    LogConfiguration::configure_stdout(LogLevel::Info, true, LOG_TAGS(jfr, startup));
    log(result, THREAD);
    LogConfiguration::configure_stdout(LogLevel::Warning, true, LOG_TAGS(jfr, startup));
  } else {
    log(result, THREAD);
  }
}

So essentially, when you don’t pass any logging configuration (and therefore the warning level is set), then JFR assumes you want to see some logging output and sets the logging level to info, but only during JFR startup.

Be aware that this also means that when you explicitly set the logging level to warning, you still see the info output for the startup. You can only turn it off by setting -Xlog:jfr+startup=error or -Xlog:jfr+startup=off. Sadly, this is documented nowhere except the source code.

Historical Reasons

But why would the OpenJDK have such confusing behaviour? It’s all due to backwards compatibility. A short git-blame pointed me to the JDK issue JDK-8244190 that resulted in the current. Before the change, the above code looked like:

if (result != NULL) {
  const char* result_chars = java_lang_String::as_utf8_string(result);
  print_message(output, result_chars);
}

So it printed the startup message no matter what. This is a problem, as explained in the issue:

JFR: When starting a JVM with -XX:StartFlightRecording, output is written to stdout

When a JVM is started with the -XX:StartFlightRecorder option, output is written to stdout indicating either success or failure that the recording is started. This breaks scripts that use Java in an interactive way to parse data, since the output message is in a non-structured form and does not match the format expected.

For example, if a Java command is being used to base64 encode an input file, and write encoded output to stdout, then it cannot be profiled with JFR in situ since the output will then no longer be correct base64 encoded output. As the goal of JFR is to allow a low-latency profiling solution that can be enabled in production, any such command whose stdout is important cannot be used in this way.

Providing a workaround option in the JFR.start DCmdStart to ignore output or have it routed elsewhere would be a way of disabling it, but a longer term option might be to use unified logging to display the message instead of stdout.

JDK-8244190

Erik Gahlin offered a few suggestions to fix the issue, but he, in the end, implemented in 2021, the proposal by David Holmes:

How about you mark the output for jfr+startup info logging and have StartFlightRecording enable that logging level if not explicitly disabled? That way the output is the same, no other output is affected and the user can still turn it off if needed. I’m just not sure we have a way to query if the logging level has been explicitly set to a given value.

David Holmes in the Discussion For JDK-8244190

Or at least I thought this was the case until David Holmes corrected me, so as a tiny tangent, here is the correction:

But what got implemented was not what I had in mind – nor, I think, is the adjustment you propose here. What I intended was along the lines of:

log_info(jfr, startup)("The startup message");

and then in the logic that starts JFR something like:

if (!log_is_enabled_on_stdout(info, jfr startup)
  Log::Configuration( /* enable jfr+startup on stdout */)

Though checking if it is enabled on stdout may be the tricky part. This was recognised in the original PR:

I have chosen to implement 5. It’s not perfect, but perhaps sufficient for now?

but you also have to allow for it being turned off explicitly by the user.

David Holmes

The Warning Logging Level

But isn’t it odd that passing -Xlog:jfr+startup=warning doesn’t stop info messages from being displayed even though it clearly sets the startup logging level to > info? The reason is in the last sentence of the previous quote by David Holmes:

I’m just not sure we have a way to query if the logging level has been explicitly set to a given value.

I checked, and there isn’t currently any code in OpenJDK’s log option parser to do this. If only I knew an OpenJDK developer who could try to add this feature. If only…

Well, as it happens, I’m an OpenJDK developer who just created a bug:

Fixing the Warning Issue

To fix the issue, I added a couple of lines to track whether a level is the default and changed the startup logging code to the following:

if (startup) {
  if (log_is_default(Warning, jfr, startup))  {
    // The user hasn't configured log level
    // Log to Info and reset to Warning. This way user can disable
    // default output by setting -Xlog:jfr+startup=error/warning/off
    LogConfiguration::configure_stdout(LogLevel::Info, true, LOG_TAGS(jfr, startup));
    log(result, THREAD);
    // we need to reset the logging propertly, so that the next
    // startup logging, works as if no logging is set
    LogConfiguration::reset_stdout(true, LOG_TAGS(jfr, startup));
  } else {
    log(result, THREAD);
  }
}

This ensures that passing -Xlog:jfr+startup=warning on the command line will prevent the JVM from printing any startup info messages.

You can find my pull request on GitHub. Will it be integrated? I don’t know. To be honest, it is not the most important issue, as it doesn’t affect production, and there is an easy workaround. Therefore, it will probably stall. The current PR comments seem to indicate this. There might also be subtle technical issues that I’m not aware of. So, for the time being, you can use this tiny JFR party trick to impress people with your in-depth knowledge on OpenJDK.

Other Possible Solutions for Quieting JFR on Startup

Erik Gahlin lists the other proposed solutions to the problem in his pull request:

1. Remove the output completely

• Con: Users will think JFR is not working since they are used to see the output
• Con: The PID must be found by other means
• Con: No hint about jcmd, or disk space being used

2. Introduce a flag to silence the output, i.e. -XX:StartFlightRecording:silent=true

• Con: Users must read documentation to find out about the option
• Con: It introduces a second mechanism to control logging
• Pro: Easy to backport. No behavioral change.

3. Write to unified logging with level Info

• Con: Users will think JFR is not working since they are used to see the output
• Con: The PID must be found by other means
• Con: No hint about jcmd, or disk space being used
• Con: Users must read documentation to find out about -Xlog:jfr+startup=info

4. Write to unified logging with level Warning

• Con: Confusing since it is not a warning.
• Pro: Users can see the tag set and turn it off easily using -Xlog:jfr+startup=off/error

Description of the Pull Request

Conclusion

The startup logging for JFR is slightly confusing, but it shows how technical limitations and backwards compatibility cause unexpected behaviour. I also showed one of the advantages of being a full-time OpenJDK developer: I implemented (and proposed) a fix for handling -Xlog:jfr+startup=warning correctly and explained why it’s probably not a pressing issue.

All this could be better documented, but I hope my blog post has done precisely this. So see you next week with a short update on my jfrevents collection website.

This blog post is part of my work in the SapMachine team at SAP, making profiling easier for everyone. Thank you to my colleague Arno for the initial question.

P.S.: This is your personal reminder to take a rest, go outside, and enjoy the sunshine, like my friend’s cat.