8338139: {ClassLoading,Memory}MXBean::isVerbose methods are inconsistent with their setVerbose methods #20628

stefank · 2024-08-19T15:39:02Z

The ClassLoadingMXBean and MemoryMXBean APIs have setVerbose methods to control verbose mode and isVerbose methods to query it. Some JCK tests expect setVerbose(false) to disable verbose mode and, subsequently, isVerbose() to return false. However, if logging to a file is enabled by using -Xlog on the java launcher command line then isVerbose() returns true even after calling setVerbose(false).

The proposed patch solves this by introducing two changes:

The previous implementation used the log_is_enabled functionality to check if logging was enabled for the given tag set. This returns true if logging has been turned on for any output. The patch changes this so that isVerbose only checks what has been configured for stdout, which is the output that setVerbose configures.
The previous implementation of setVerbose turned on class+load* (notice the star) but then isVerbose only checked class+load (without the star). The patch changes this so that the isVerbose in-effect checks class+load*. (The gc part of the patch did not have this problem)

The main focus on this patch is to fix the JCK failure, with an implementation that follows the API documentation. While looking at this area of the code it is clear that there are other problems that we might want to addressed in the future, but we're intentionally keeping this patch limited in scope so that it can be backported to JDK 23.

A CSR for this change has been created.

Testing:

The newly implemented tests
The failing JCK tests with the corresponding -Xlog lines
Tier1-7 (running)

The patch is co-authored by me and David Holmes

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
Change requires CSR request JDK-8338540 to be approved

Issues

JDK-8338139: {ClassLoading,Memory}MXBean::isVerbose methods are inconsistent with their setVerbose methods (Bug - P1)
JDK-8338540: {ClassLoading,Memory}MXBean::isVerbose methods are inconsistent with their setVerbose methods (CSR)

Reviewers

Leonid Mesnik (@lmesnik - Reviewer)
Daniel D. Daugherty (@dcubed-ojdk - Reviewer)
David Holmes (@dholmes-ora - Reviewer)

Contributors

David Holmes <dholmes@openjdk.org>

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 20628

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

Using diff file

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

Webrev

Link to Webrev Comment

Co-authored-by: David Holmes <david.holmes@oracle.com>

bridgekeeper · 2024-08-19T15:39:27Z

👋 Welcome back stefank! 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 · 2024-08-19T15:39:36Z

@stefank This change now passes all automated pre-integration checks.

ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details.

After integration, the commit message for the final commit will be:

8338139: {ClassLoading,Memory}MXBean::isVerbose methods are inconsistent with their setVerbose methods

Co-authored-by: David Holmes <dholmes@openjdk.org>
Reviewed-by: lmesnik, dcubed, dholmes

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been 126 new commits pushed to the master branch:

55851a3: 8281533: Odd "preview" label in link/linkplain
c7690c3: 8338190: TOC vertical offsets not updated when document size changes
6460b30: 8321140: Add comment to note difference in Metal's JButton margins
3ca359a: 8335771: Improve stability of java/nio/channels/DatagramChannel tests
2766b09: 8338452: (dc) DatagramChannelImpl.blockingReceive with timeout may block indefinitely if all datagrams blocked by SecurityManager
f0fe313: 8338564: Remove obsolete AbstractNamedEntry::equals method
6ff6b09: 8290501: Typo in javax.swing.BoundedRangeModel documentation
e07a5b6: 8338512: JFR: Revert changes to TestCodeSweeper
6d430f2: 8338314: JFR: Split JFRCheckpoint VM operation
f0374a0: 8337987: Relocate jfr and throw_exception stubs from StubGenerator to SharedRuntime
... and 116 more: https://git.openjdk.org/jdk/compare/21f710e7f6698b12b06cc3685cefa31f5fcff2a2...master

As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details.

➡️ To integrate this PR with the above commit message to the master branch, type /integrate in a new comment.

openjdk · 2024-08-19T15:40:05Z

@stefank The following labels will be automatically applied to this pull request:

core-libs
hotspot-runtime
serviceability

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

mlbridge · 2024-08-19T15:43:22Z

Webrevs

01: Full - Incremental (352d0a46)
00: Full (bc51417e)

stefank · 2024-08-19T15:46:49Z

/contributor add @dholmes-ora

openjdk · 2024-08-19T15:48:15Z

@stefank
Contributor David Holmes <dholmes@openjdk.org> successfully added.

AlanBateman · 2024-08-19T16:04:58Z

/label remove core-libs

openjdk · 2024-08-19T16:06:31Z

@AlanBateman
The core-libs label was successfully removed.

lmesnik · 2024-08-19T16:26:02Z

test/jdk/java/lang/management/MemoryMXBean/TestVerboseMemory.java

+ * @summary Basic unit test of TestVerboseMemory.set/isVerbose() when
+ *          related unified logging is enabled.
+ *
+ * @run main/othervm -Xlog:gc=trace:file=vm.log TestVerboseMemory false


Does it makes sense to add case where not only 'gc' logging is set from CLI with file output? It would be the exact copy of failed case.

@run main/othervm -Xlog:all=trace:file=vm.log TestVerboseMemory false

(Same for ClassLoading Bean)

Yes, that's a good suggestion. I've updated the tests.

dcubed-ojdk

Thumbs up.

dcubed-ojdk · 2024-08-19T16:30:09Z

src/hotspot/share/services/memoryService.cpp

+bool MemoryService::get_verbose() {
+  for (LogTagSet* ts = LogTagSet::first(); ts != nullptr; ts = ts->next()) {
+    // set_verbose only sets gc and not gc*, so check for an exact match
+    const bool is_gc_exact_match = ts->contains(LogTag::_gc) && ts->ntags() == 1;
+    if (is_gc_exact_match) {
+      LogLevelType l = ts->level_for(LogConfiguration::StdoutLog);
+      if (l == LogLevel::Info || l == LogLevel::Debug || l == LogLevel::Trace) {
+        return true;
+      }
+    }
+  }
+
+  return false;
+}


If we have -Xlog:gc and -Xlog:gc+foo set I think this version of
MemoryService::get_verbose() will return false. Is that really
what we want?

Update: Looks like the CSR says that's exactly what we want.

Wait. This is not what the implementation does. If you specify -Xlog:gc and -Xlog:gc+init (using a real tag instead of foo), get_verbose will return true. It only cares about the tag set that is exactly 'gc' and ignores the 'gc+init' tag set.

I'm adding a test line to show that.

So in this test case:
-Xlog:gc,gc+init
you have it so that true is returned.

With this line of code:

const bool is_gc_exact_match = ts->contains(LogTag::_gc) && ts->ntags() == 1;

I would think that this part is false: ts->ntags() == 1
for the -Xlog:gc,gc+init test case so we'll be returning false.

What am I missing?

The important part is that ts contains one single tag set and that gc,gc+init is a string that specifies the two tag sets gc and gc+init. Also, note that -Xlog:gc,gc+init and -Xlog:gc -Xlog:gc+init is effectively the same.

It is also important to understand that the for loop iterates over all tag sets that have been used in the HotSpot code. It is not iterating over the tag sets specified by -Xlog lines.

OK, I get it now. The loop cycles thru the tag set and finds one that is
a singleton and an exact match, i.e., -Xlog:gc. With -Xlog:gc+init,
the ts->ntags() == 1 would be false because that one is not an
exact match.

I misunderstood the algorithm a bit. Sorry for the noise.

dcubed-ojdk · 2024-08-19T16:33:49Z

test/jdk/java/lang/management/ClassLoadingMXBean/TestVerboseClassLoading.java

+ * @run main/othervm -Xlog:class+load=trace TestVerboseClassLoading false
+ * @run main/othervm -Xlog:class+load=debug TestVerboseClassLoading false
+ * @run main/othervm -Xlog:class+load=info TestVerboseClassLoading false


Hmm... I was expecting these to be true. What am I missing?

Update: The CSR makes it clear that it is -Xlog:class+load* so all have to be set.

This is one of those places where we changed the behavior. Previously, 'isVerbose` would return true here.

Yup. We're in agreement here.

dcubed-ojdk · 2024-08-19T16:40:55Z

test/jdk/java/lang/management/ClassLoadingMXBean/TestVerboseClassLoading.java

+ * @run main/othervm -Xlog:class+load*=info,class+load+cause=off TestVerboseClassLoading false
+ */
+
+import java.lang.management.*;


I thought we tried to avoid wild-card imports.

I also tend to avoid wild-card imports, so I've updated the tests. (FWIW, the management package is full of wild-card imports, so it's unclear if we actually do try to avoid it for this part of the source code)

dcubed-ojdk · 2024-08-19T16:41:15Z

test/jdk/java/lang/management/MemoryMXBean/TestVerboseMemory.java

+ * @run main/othervm -Xlog:gc=off,gc+init=info TestVerboseMemory false
+ */
+
+import java.lang.management.*;


I thought we tried to avoid wild-card imports.

I thought we tried to avoid wild-card imports.

Contrary to common opinion, there is no ban on wild-card imports.

lmesnik

Tests looks good.

dholmes-ora

LGTM! Thanks for taking this over @stefank !

dcubed-ojdk · 2024-08-19T22:12:50Z

test/jdk/java/lang/management/ClassLoadingMXBean/TestVerboseClassLoading.java

+ * @run main/othervm -Xlog:class+load=trace TestVerboseClassLoading false
+ * @run main/othervm -Xlog:class+load=debug TestVerboseClassLoading false
+ * @run main/othervm -Xlog:class+load=info TestVerboseClassLoading false


Yup. We're in agreement here.

dcubed-ojdk · 2024-08-19T22:22:26Z

src/hotspot/share/services/memoryService.cpp

+bool MemoryService::get_verbose() {
+  for (LogTagSet* ts = LogTagSet::first(); ts != nullptr; ts = ts->next()) {
+    // set_verbose only sets gc and not gc*, so check for an exact match
+    const bool is_gc_exact_match = ts->contains(LogTag::_gc) && ts->ntags() == 1;
+    if (is_gc_exact_match) {
+      LogLevelType l = ts->level_for(LogConfiguration::StdoutLog);
+      if (l == LogLevel::Info || l == LogLevel::Debug || l == LogLevel::Trace) {
+        return true;
+      }
+    }
+  }
+
+  return false;
+}


So in this test case:
-Xlog:gc,gc+init
you have it so that true is returned.

With this line of code:

const bool is_gc_exact_match = ts->contains(LogTag::_gc) && ts->ntags() == 1;

I would think that this part is false: ts->ntags() == 1
for the -Xlog:gc,gc+init test case so we'll be returning false.

What am I missing?

stefank · 2024-08-20T06:15:07Z

Thanks all for reviewing. This passed tier1-7 and my local runs of JCK.
/integrate

openjdk · 2024-08-20T06:15:59Z

Going to push as commit 9775d57.
Since your change was applied there have been 127 commits pushed to the master branch:

68d1f5c: 8338543: ClassBuilder withMethod builders should cache the method type symbol
55851a3: 8281533: Odd "preview" label in link/linkplain
c7690c3: 8338190: TOC vertical offsets not updated when document size changes
6460b30: 8321140: Add comment to note difference in Metal's JButton margins
3ca359a: 8335771: Improve stability of java/nio/channels/DatagramChannel tests
2766b09: 8338452: (dc) DatagramChannelImpl.blockingReceive with timeout may block indefinitely if all datagrams blocked by SecurityManager
f0fe313: 8338564: Remove obsolete AbstractNamedEntry::equals method
6ff6b09: 8290501: Typo in javax.swing.BoundedRangeModel documentation
e07a5b6: 8338512: JFR: Revert changes to TestCodeSweeper
6d430f2: 8338314: JFR: Split JFRCheckpoint VM operation
... and 117 more: https://git.openjdk.org/jdk/compare/21f710e7f6698b12b06cc3685cefa31f5fcff2a2...master

Your commit was automatically rebased without conflicts.

openjdk · 2024-08-20T06:16:04Z

@stefank Pushed as commit 9775d57.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.

stefank · 2024-08-20T12:36:26Z

/backport :jdk23

openjdk · 2024-08-20T12:37:49Z

@stefank the backport was successfully created on the branch backport-stefank-9775d571-jdk23 in my personal fork of openjdk/jdk. To create a pull request with this backport targeting openjdk/jdk:jdk23, just click the following link:

➡️ Create pull request

The title of the pull request is automatically filled in correctly and below you find a suggestion for the pull request body:

Hi all,

This pull request contains a backport of commit 9775d571 from the openjdk/jdk repository.

The commit being backported was authored by Stefan Karlsson on 20 Aug 2024 and was reviewed by Leonid Mesnik, Daniel D. Daugherty and David Holmes.

Thanks!

If you need to update the source branch of the pull then run the following commands in a local clone of your personal fork of openjdk/jdk:

$ git fetch https://github.com/openjdk-bots/jdk.git backport-stefank-9775d571-jdk23:backport-stefank-9775d571-jdk23
$ git checkout backport-stefank-9775d571-jdk23
# make changes
$ git add paths/to/changed/files
$ git commit --message 'Describe additional changes made'
$ git push https://github.com/openjdk-bots/jdk.git backport-stefank-9775d571-jdk23

8338139: The MXBean isVerbose() is always on when Xlog is enabled

bc51417

Co-authored-by: David Holmes <david.holmes@oracle.com>

stefank marked this pull request as ready for review August 19, 2024 15:39

openjdk bot added the rfr Pull request is ready for review label Aug 19, 2024

openjdk bot added serviceability serviceability-dev@openjdk.org hotspot-runtime hotspot-runtime-dev@openjdk.org core-libs core-libs-dev@openjdk.org labels Aug 19, 2024

openjdk bot removed the core-libs core-libs-dev@openjdk.org label Aug 19, 2024

lmesnik suggested changes Aug 19, 2024

View reviewed changes

openjdk bot added the csr Pull request needs approved CSR before integration label Aug 19, 2024

dcubed-ojdk approved these changes Aug 19, 2024

View reviewed changes

stefank added 2 commits August 19, 2024 21:40

Review comments

b1dd6e6

Test -Xlog:gc,gc+init

352d0a4

lmesnik approved these changes Aug 19, 2024

View reviewed changes

openjdk bot added ready Pull request is ready to be integrated and removed csr Pull request needs approved CSR before integration labels Aug 19, 2024

dholmes-ora approved these changes Aug 19, 2024

View reviewed changes

dcubed-ojdk approved these changes Aug 19, 2024

View reviewed changes

openjdk bot added the integrated Pull request has been integrated label Aug 20, 2024

openjdk bot closed this Aug 20, 2024

openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels Aug 20, 2024

8338139: {ClassLoading,Memory}MXBean::isVerbose methods are inconsistent with their setVerbose methods #20628

8338139: {ClassLoading,Memory}MXBean::isVerbose methods are inconsistent with their setVerbose methods #20628

Conversation

stefank commented Aug 19, 2024 • edited by openjdk bot Loading

Progress

Issues

Reviewers

Contributors

Reviewing

Webrev

bridgekeeper bot commented Aug 19, 2024

openjdk bot commented Aug 19, 2024 • edited Loading

openjdk bot commented Aug 19, 2024

mlbridge bot commented Aug 19, 2024 • edited Loading

Webrevs

stefank commented Aug 19, 2024

openjdk bot commented Aug 19, 2024

AlanBateman commented Aug 19, 2024

openjdk bot commented Aug 19, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dcubed-ojdk left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dcubed-ojdk Aug 19, 2024 • edited Loading

Choose a reason for hiding this comment

stefank Aug 20, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lmesnik left a comment

Choose a reason for hiding this comment

dholmes-ora left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dcubed-ojdk Aug 19, 2024 • edited Loading

Choose a reason for hiding this comment

stefank commented Aug 20, 2024

openjdk bot commented Aug 20, 2024

openjdk bot commented Aug 20, 2024

stefank commented Aug 20, 2024

openjdk bot commented Aug 20, 2024

stefank commented Aug 19, 2024 •

edited by openjdk bot

Loading

openjdk bot commented Aug 19, 2024 •

edited

Loading

mlbridge bot commented Aug 19, 2024 •

edited

Loading

dcubed-ojdk Aug 19, 2024 •

edited

Loading

stefank Aug 20, 2024 •

edited

Loading

dcubed-ojdk Aug 19, 2024 •

edited

Loading