8366232: JFR startup messages are shown with -Xlog:jfr+startup=warning

[parttimenerd]

Only print the JFR startup messages when no or a < warning log level is set explicitly by the user.

---

Progress

• Change must be properly reviewed (1 review required, with at least 1 Reviewer)
• Change must not contain extraneous whitespace
• Commit message must refer to an issue

Issue

• JDK-8366232: JFR startup messages are shown with -Xlog:jfr+startup=warning (Enhancement - P4)

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.org/jdk.git pull/26957/head:pull/26957
$ git checkout pull/26957

Update a local copy of the PR:
$ git checkout pull/26957
$ git pull https://git.openjdk.org/jdk.git pull/26957/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 26957

View PR using the GUI difftool:
$ git pr show -t 26957

Using diff file

Download this PR as a diff file:
https://git.openjdk.org/jdk/pull/26957.diff

Using Webrev

Link to Webrev Comment

[bridgekeeper]

👋 Welcome back jbechberger! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

[openjdk]

❗ This change is not yet ready to be integrated.
See the Progress checklist in the description for automated requirements.

[openjdk]

@parttimenerd The following label will be automatically applied to this pull request:

• hotspot

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

[mlbridge]

Webrevs

• 02: Full - Incremental (4b827459)
• 01: Full - Incremental (56cef57f)
• 00: Full (95c47b2a)

[dholmes-ora]

/label add hotspot-jfr
/label add hotspot-runtime
/label remove hotspot

[openjdk]

@dholmes-ora
The hotspot-jfr label was successfully added.

[openjdk]

@dholmes-ora
The hotspot-runtime label was successfully added.

[openjdk]

@dholmes-ora
The hotspot label was successfully removed.

[dholmes-ora]

I can't say I like the general changes to UL to accommodate this. I also don't really like what JFR is already doing. I'm trying to see what the motivation is here. It appears to be "give a verbose startup message but don't label it as a 'warning'". But there is also no guarantee that jfr+startup is being logged to stdout so this could by-pass the user's control over logging output!

[parttimenerd]

The motivation is to better capture the user's intent. When the user doesn't set any warning level, then we keep the default behaviour, for backwards compatibility as in the original change, when the user sets the logging level, then we consider it.

You mentioned yourself in the original issue:

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

I just implemented this. I just implemented a way to properly check whether the user didn't specify a logging level, so the code doesn't have to assume that a warning logging level means the user didn't set anything.

This change tries to reduce confusion.

[dholmes-ora]

What was the original issue? I have forgotten about this.

[parttimenerd]

The original issue was JDK-8244190, this PR just fixes a short-coming of the implementation. The limitations is even mentioned in one of the tests:

        startJfrJvm("-Xlog:jfr+startup=error")
             .shouldNotContain("[jfr,startup")
             .shouldNotContain("Started recording")
             .shouldNotContain("Use jcmd");

         // Known limitation.
         // Can't turn off log with -Xlog:jfr+startup=warning

         startJfrJvm()
             .shouldContain("[info][jfr,startup")
             .shouldContain("Started recording")
             .shouldContain("Use jcmd");

This PR updates the test too.

[dholmes-ora]

The original issue was JDK-8244190, this PR just fixes a short-coming of the implementation.

Okay in the original JBS issue I wrote:

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.

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.

[parttimenerd]

But isn't my PR closer to what the user expects? When you explicitly set the level to warning, no info level messages should be printed

[dholmes-ora]

Functionally yes, but I'm just not sure about the mechanism. Need to think more about it. This reminds me of the flag complexity: FLAG_IS_DEFAULT, FLAG_IS_CMDLINE etc.

[egahlin]

Does your change handle logging to a file?

I looked into fixing this when I did the initial implementation, but I didn't think it was worth addressing. It only applies to jfr+startup and if the user wants the warning level. If a user doesn't want the message, they can specify jfr+startup=error.

Do we log anything with jfr+startup=warning?

[parttimenerd]

Without this change, jfr+startup=warning doesn't affect the startup logging at all, and it shows the startup message, which was confusing to one of our users (why is it showing [info] tagged startup messages when the warning level is set).

I'll look into how it handles files later in the day

[parttimenerd]

Regarding files:

-Xlog:jfr+startup=info:file=a.txt causes the startup message to be written to the file, but -Xlog:jfr+startup=warning:file=a.txt doesn't.

So it works both for files and stdout, the implementation changes the behaviour at the root.

[TheRealMDoerr]

This PR needs an update since Atomic has been renamed to AtomicAccess.