Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

8330198: Add some class loading related perf counters to measure VM startup #18790

Closed

Conversation

calvinccheung
Copy link
Member

@calvinccheung calvinccheung commented Apr 16, 2024

Adding a few perf counters related to class loading to measure VM startup. The counters are only active if the user specifies -Xlog:init in the command line. A diagnostic flag ProfileClassLinkage is added to control the new counters. The flag is set to false by default and will be enabled if -Xlog:init is specified.

This change is already in the leyden/premain branch. There are more counters in the branch to measure other stuff. For now, just upstreaming class loader related counters.

Refer to the comment in the bug report for an example output.

Passed tiers 1 - 4 testing.


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-8330198: Add some class loading related perf counters to measure VM startup (Enhancement - P4)

Reviewers

Contributors

  • Vladimir Ivanov <vlivanov@openjdk.org>

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 18790

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

Using diff file

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

Webrev

Link to Webrev Comment

@bridgekeeper
Copy link

bridgekeeper bot commented Apr 16, 2024

👋 Welcome back ccheung! 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
Copy link

openjdk bot commented Apr 16, 2024

@calvinccheung 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:

8330198: Add some class loading related perf counters to measure VM startup

Co-authored-by: Vladimir Ivanov <vlivanov@openjdk.org>
Reviewed-by: iklam, 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 184 new commits pushed to the master branch:

  • bb7ef03: 8333599: Improve description of \b matcher in j.u.r.Pattern
  • 0721dbe: 8334032: javax.print: Missing @SInCE tag in new class OutputBin
  • 6462b87: 8333685: Make update-copyright-year script more useful
  • b09a451: 8333840: C2 SuperWord: wrong result for MulAddS2I when inputs permuted
  • cff048c: 8334162: Gatherer.defaultCombiner has an erronous @see-link
  • 814cf87: 8313562: hsperfdata should export module path and "launcher" metadata
  • 9ed8629: 8333801: Typos in @code references of BufferedImage and JTableHeader
  • 0d3a377: 8333887: ubsan: unsafe.cpp:247:13: runtime error: store to null pointer of type 'volatile int'
  • 9d8439c: 8211854: [aix] java/net/ServerSocket/AcceptInheritHandle.java fails: read times out
  • f521367: 8211847: [aix] java/lang/ProcessHandle/InfoTest.java fails: "reported cputime less than expected"
  • ... and 174 more: https://git.openjdk.org/jdk/compare/10eb1cb639095caa2636cc87c45201d4f8cf1eb4...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
Copy link

openjdk bot commented Apr 16, 2024

@calvinccheung 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.

@openjdk openjdk bot added the hotspot hotspot-dev@openjdk.org label Apr 16, 2024
@openjdk
Copy link

openjdk bot commented Apr 16, 2024

@calvinccheung this pull request can not be integrated into master due to one or more merge conflicts. To resolve these merge conflicts and update this pull request you can run the following commands in the local repository for your personal fork:

git checkout xloginit-classloading
git fetch https://git.openjdk.org/jdk.git master
git merge FETCH_HEAD
# resolve conflicts and follow the instructions given by git merge
git commit -m "Merge master"
git push

@openjdk openjdk bot added the merge-conflict Pull request has merge conflict with target branch label Apr 16, 2024
@openjdk openjdk bot removed the merge-conflict Pull request has merge conflict with target branch label Apr 17, 2024
@calvinccheung calvinccheung marked this pull request as ready for review April 17, 2024 18:53
@openjdk openjdk bot added the rfr Pull request is ready for review label Apr 17, 2024
@mlbridge
Copy link

mlbridge bot commented Apr 17, 2024

@openjdk openjdk bot added the merge-conflict Pull request has merge conflict with target branch label May 9, 2024
@openjdk openjdk bot removed the merge-conflict Pull request has merge conflict with target branch label May 10, 2024
src/hotspot/share/runtime/java.cpp Outdated Show resolved Hide resolved
src/hotspot/share/runtime/perfData.hpp Outdated Show resolved Hide resolved
src/hotspot/share/runtime/perfData.hpp Outdated Show resolved Hide resolved
Copy link
Member

@iklam iklam left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@openjdk openjdk bot added the ready Pull request is ready to be integrated label May 15, 2024
@calvinccheung
Copy link
Member Author

/contributor add iwanowww

@openjdk
Copy link

openjdk bot commented May 15, 2024

@calvinccheung iwanowww was not found in the census.

Syntax: /contributor (add|remove) [@user | openjdk-user | Full Name <email@address>]. For example:

  • /contributor add @openjdk-bot
  • /contributor add duke
  • /contributor add J. Duke <duke@openjdk.org>

User names can only be used for users in the census associated with this repository. For other contributors you need to supply the full name and email address.

@calvinccheung
Copy link
Member Author

/contributor add vlivanov

@openjdk
Copy link

openjdk bot commented May 15, 2024

@calvinccheung
Contributor Vladimir Ivanov <vlivanov@openjdk.org> successfully added.

Copy link
Member

@dholmes-ora dholmes-ora left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Okay my first reaction here is "I object!". I get that Leyden wants to be able to easily compare startup costs between itself and mainline, but what is this costing mainline? Even if these counters are not active there is an impact on the code execution and I want to know that impact is negligible.

The initialization logic seems a little off to me too - see comments below.

src/hotspot/share/classfile/classLoader.cpp Outdated Show resolved Hide resolved
src/hotspot/share/classfile/classLoader.cpp Outdated Show resolved Hide resolved
src/hotspot/share/oops/instanceKlass.cpp Outdated Show resolved Hide resolved
src/hotspot/share/runtime/perfData.hpp Outdated Show resolved Hide resolved
src/hotspot/share/runtime/perfData.hpp Outdated Show resolved Hide resolved
src/hotspot/share/runtime/arguments.cpp Outdated Show resolved Hide resolved
@calvinccheung
Copy link
Member Author

Okay my first reaction here is "I object!". I get that Leyden wants to be able to easily compare startup costs between itself and mainline, but what is this costing mainline? Even if these counters are not active there is an impact on the code execution and I want to know that impact is negligible.

I added some perf numbers for various startup benchmarks in the bug report comment.

@iklam
Copy link
Member

iklam commented May 25, 2024

Okay my first reaction here is "I object!". I get that Leyden wants to be able to easily compare startup costs between itself and mainline, but what is this costing mainline? Even if these counters are not active there is an impact on the code execution and I want to know that impact is negligible.

These counters are useful in the mainline as well. We want to be able to use java -Xlog:init to diagnose start-up time performance for the mainline.

The main cost of the performance counters is reading of the clock. All the new counters added in the PR are guarded by a global flag, so the cost is negligible when the logging is not enabled.

Copy link
Member

@dholmes-ora dholmes-ora left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I have a few concerns about the way this is being put together. The coupling between the use of the perf counters and the unified logging seems awkward to me.

src/hotspot/share/cds/dynamicArchive.cpp Outdated Show resolved Hide resolved
src/hotspot/share/classfile/classLoader.cpp Outdated Show resolved Hide resolved
src/hotspot/share/runtime/arguments.cpp Outdated Show resolved Hide resolved
src/hotspot/share/runtime/perfData.hpp Outdated Show resolved Hide resolved
src/hotspot/share/runtime/threads.cpp Outdated Show resolved Hide resolved
src/hotspot/share/runtime/java.cpp Outdated Show resolved Hide resolved
src/hotspot/share/runtime/java.cpp Outdated Show resolved Hide resolved
Copy link
Member

@dholmes-ora dholmes-ora left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I can't decide whether using the logging state to control the counter initialization as well as their printing is clever, or combining things the wrong way.

When you have additional counters enabled by slightly different logging settings, I can't see how you will compose things.

I also still wonder about the overhead of the empty perf timer events in heavy duty classloading applications.

src/hotspot/share/runtime/java.cpp Outdated Show resolved Hide resolved
src/hotspot/share/runtime/java.cpp Outdated Show resolved Hide resolved
Comment on lines 831 to 835
if (log_is_enabled(Info, perf, class, link)) {
LogStreamHandle(Info, perf, class, link) log;
log.print_cr("At VM initialization completion:");
log_vm_stats(&log);
}
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If we are going to have more types of VM stats in the future, it is not clear how you will change this if-condition? Nor what stream you would pass in. ???

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The if-condition could be something like:

if (log_is_enabled(Info, perf, class, link) ||
     log_is_enabled(Info, perf, xxx, yyy) ||
     ...)

Regarding which stream to pass in, with my proposed change in log_vm_stats above, the current fix would look like when calling from threads.cpp:
log_vm_stats(false /* use_tty */);
when calling from java.cpp:
log_vm_stats(true /* use_tty */);

Or do you prefer not having the log_vm_stats function and calling ClassLoader::print_counters directly?
If so, we don't need the compound if conditions in the above.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The problem is that the two different logging configurations could have been given different destinations and need not write to the same "stream".

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it's better not to have log_vm_stats but calling ClassLoader::print_counters directly. Otherwise, in log_vm_stats, it needs to check every -Xlog:perf+... tag like the following:

void log_vm_stats(bool use_tty) {
  LogStreamHandle(Info, perf, class, link) log;
  if (log.is_enabled()) {
    outputStream* st = use_tty ? tty : &log;
    ClassLoader::print_counters(st);
  }
  LogStreamHandle(Info, perf, xxx, yyy) log2;
  if (log2.is_enabled()) {
    outputStream* st = use_tty ? tty : &log2;
    XXX::print_counters(st);
   }
  ...
}

I've pushed another commit without log_vm_stats.
Also checked the performance using the PetClinic app which loads more than 17,000 classes during boot up. Not much performance difference was observed.

Comment on lines 360 to 362
if (log_is_enabled(Info, perf, class, link)) {
ClassLoader::print_counters(tty);
}
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Again this needs to comment why we check the log is active but write to tty instead of the logstream.

Or we could put the log_is_enabled check inside print_counters rather than require callers to do it. That also allows us to print that the counters are disabled eg.

void ClassLoader::print_counters(outputStream *st) {
  // The counters are only active if the logging is enabled, but
  // we print to the passed in outputStream as requested.
  if (log_is_enabled(Info, perf, class, link)) {
    st->print_cr("ClassLoader:");
    ...
  } else {
    st->print_cr("ClassLoader: <not enabled>");
  }

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've made the above changes as you suggested without the else part to be consistent with printing of other statistics.

Copy link
Member

@dholmes-ora dholmes-ora left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Okay. But lets see if @iklam is happy with where things ended up before integrating.

Thanks

Copy link
Member

@iklam iklam left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Latest version looks good.

@calvinccheung
Copy link
Member Author

Thanks @iklam, @dholmes-ora for the review.

/integrate

@openjdk
Copy link

openjdk bot commented Jun 14, 2024

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

  • c4702ca: 8333827: JDK 23 RDP1 L10n resource files update
  • bb7ef03: 8333599: Improve description of \b matcher in j.u.r.Pattern
  • 0721dbe: 8334032: javax.print: Missing @SInCE tag in new class OutputBin
  • 6462b87: 8333685: Make update-copyright-year script more useful
  • b09a451: 8333840: C2 SuperWord: wrong result for MulAddS2I when inputs permuted
  • cff048c: 8334162: Gatherer.defaultCombiner has an erronous @see-link
  • 814cf87: 8313562: hsperfdata should export module path and "launcher" metadata
  • 9ed8629: 8333801: Typos in @code references of BufferedImage and JTableHeader
  • 0d3a377: 8333887: ubsan: unsafe.cpp:247:13: runtime error: store to null pointer of type 'volatile int'
  • 9d8439c: 8211854: [aix] java/net/ServerSocket/AcceptInheritHandle.java fails: read times out
  • ... and 175 more: https://git.openjdk.org/jdk/compare/10eb1cb639095caa2636cc87c45201d4f8cf1eb4...master

Your commit was automatically rebased without conflicts.

@openjdk openjdk bot added the integrated Pull request has been integrated label Jun 14, 2024
@openjdk openjdk bot closed this Jun 14, 2024
@openjdk openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels Jun 14, 2024
@openjdk
Copy link

openjdk bot commented Jun 14, 2024

@calvinccheung Pushed as commit eb2488f.

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

@calvinccheung calvinccheung deleted the xloginit-classloading branch June 14, 2024 01:21
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
hotspot hotspot-dev@openjdk.org integrated Pull request has been integrated
4 participants