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

8266936: Add a finalization JFR event #4731

Closed
wants to merge 28 commits into from

Conversation

mgronlun
Copy link

@mgronlun mgronlun commented Jul 8, 2021

Greetings,

Object.finalize() was deprecated in JDK9. There is an ongoing effort to replace and mitigate Object.finalize() uses in the JDK libraries; please see https://bugs.openjdk.java.net/browse/JDK-8253568 for more information.

We also like to assist users in replacing and mitigating uses in non-JDK code.

Hence, this changeset adds a periodic JFR event to help identify which classes are overriding Object.finalize().

Thanks
Markus


Progress

  • Change must not contain extraneous whitespace
  • Commit message must refer to an issue
  • Change must be properly reviewed

Issue

Reviewers

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.java.net/jdk pull/4731/head:pull/4731
$ git checkout pull/4731

Update a local copy of the PR:
$ git checkout pull/4731
$ git pull https://git.openjdk.java.net/jdk pull/4731/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 4731

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

Using diff file

Download this PR as a diff file:
https://git.openjdk.java.net/jdk/pull/4731.diff

@bridgekeeper
Copy link

bridgekeeper bot commented Jul 8, 2021

👋 Welcome back mgronlun! 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 Jul 8, 2021

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

  • hotspot-jfr

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-jfr hotspot-jfr-dev@openjdk.org label Jul 8, 2021
@mgronlun
Copy link
Author

mgronlun commented Jul 8, 2021

/label core-libs

@openjdk openjdk bot added the core-libs core-libs-dev@openjdk.org label Jul 8, 2021
@openjdk
Copy link

openjdk bot commented Jul 8, 2021

@mgronlun
The core-libs label was successfully added.

@openjdk openjdk bot added the rfr Pull request is ready for review label Jul 9, 2021
@@ -1081,6 +1081,10 @@
<Field type="uint" name="stallCount" label="Stall Count" description="The number of Java threads stalled by the GC locker" />
</Event>

<Event name="Finalizer" category="Java Application" label="Finalizer" thread="false" startTime="false" period="endChunk">
Copy link
Member

@bchristi-git bchristi-git Jul 9, 2021

Choose a reason for hiding this comment

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

Would it make sense for this event to be under the "Java Virtual Machine, GC" category?

Copy link
Author

@mgronlun mgronlun Jul 10, 2021

Choose a reason for hiding this comment

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

My argument for placing the event in the Java Application category:

The finalization concept is, or maybe more correctly has been, reified in the Java language. The Java programmer decides to enlist the exposed functionality, similar to Java language Exceptions and Errors. JFR already represents events for these latter concepts in the Java Application category because programmers directly interact with and, in contrast to many events in the JVM category, have more control over them.

@mlchung
Copy link
Member

mlchung commented Jul 12, 2021

This approach inspecting the loaded classes periodically as well as tracking the classes being unloaded looks good. A class with the same class name may be loaded from different class loader and could also be loaded from different code source. It'd be useful for the finalizer event to include the code source which is passed from defineClass to help identify where the class was loaded from.

@mgronlun
Copy link
Author

mgronlun commented Jul 20, 2021

Thanks @mlchung.

The JFR model has an intrinsic relation between a class and its class loader, which is persisted in the recording.

The code source is not saved in the VM as part of the InstanceKlass, but one could get to the associated ProtectionDomain (if one exist) through the mirror class. The "codesource" field of the ProtectionDomain can be used to read the "locationfNoFragString" which could then be saved as a "codesource" event field.

@mlchung
Copy link
Member

mlchung commented Jul 20, 2021

@openjdk
Copy link

openjdk bot commented Jul 27, 2021

⚠️ @mgronlun This pull request contains merges that bring in commits not present in the target repository. Since this is not a "merge style" pull request, these changes will be squashed when this pull request in integrated. If this is your intention, then please ignore this message. If you want to preserve the commit structure, you must change the title of this pull request to Merge <project>:<branch> where <project> is the name of another project in the OpenJDK organization (for example Merge jdk:master).

@mlbridge
Copy link

mlbridge bot commented Jul 27, 2021

Mailing list message from Bernd Eckenfels on core-libs-dev:

Hello,

I know I am a bit late, but just wanted to mention, that since finding finalizers with Bytecode analysis is doable (and probably easier to deal with such scan reports), I don?t see much value in a JFR event, especially considering it even has native code executed. (Not so sure about dynamically loaded classes, would the event content help to identify sources?)

Having said that, this event would be more useful from a runtime perspective if It would actually record execution counts and time per class. Then one can concentrate on the worst offenders, first and even use it for runtime monitoring. Is there already a finalizer profiler?

Gruss
Bernd
--
http://bernd.eckenfels.net
________________________________
Von: core-libs-dev <core-libs-dev-retn at openjdk.java.net> im Auftrag von Markus Gr?nlund <mgronlun at openjdk.java.net>
Gesendet: Tuesday, July 27, 2021 5:14:29 PM
An: core-libs-dev at openjdk.java.net <core-libs-dev at openjdk.java.net>; hotspot-jfr-dev at openjdk.java.net <hotspot-jfr-dev at openjdk.java.net>
Betreff: Re: RFR: 8266936: Add a finalization JFR event [v4]

Greetings,

Object.finalize() was deprecated in JDK9. There is an ongoing effort to replace and mitigate Object.finalize() uses in the JDK libraries; please see https://bugs.openjdk.java.net/browse/JDK-8253568 for more information.

We also like to assist users in replacing and mitigating uses in non-JDK code.

Hence, this changeset adds a periodic JFR event to help identify which classes are overriding Object.finalize().

Thanks
Markus

Markus Gr?nlund has updated the pull request incrementally with one additional commit since the last revision:

remove build directive

-------------

Changes:
- all: https://git.openjdk.java.net/jdk/pull/4731/files
- new: https://git.openjdk.java.net/jdk/pull/4731/files/58fc3f0a..4498803

Webrevs:
- full: https://webrevs.openjdk.java.net/?repo=jdk&pr=4731&range=03
- incr: https://webrevs.openjdk.java.net/?repo=jdk&pr=4731&range=02-03

Stats: 1 line in 1 file changed: 0 ins; 1 del; 0 mod
Patch: https://git.openjdk.java.net/jdk/pull/4731.diff
Fetch: git fetch https://git.openjdk.java.net/jdk pull/4731/head:pull/4731

PR: https://git.openjdk.java.net/jdk/pull/4731

@bchristi-git
Copy link
Member

bchristi-git commented Jul 28, 2021

Hi, Bernd

The JFR event can complement static bytecode analysis, reporting which classes with finalizers actually get loaded at runtime.

I agree that it would be useful to add a count for finalizers that get run, either as part of this PR, or as a follow-up. I would hesitate to add timing, though. It's important to keep the overhead of this event low, and finalize() methods should already show up in current profilers.

Thanks,
-Brent

Mailing list message from Bernd Eckenfels on core-libs-dev:

Hello,

I know I am a bit late, but just wanted to mention, that since finding finalizers with Bytecode analysis is doable (and probably easier to deal with such scan reports), I don?t see much value in a JFR event, especially considering it even has native code executed. (Not so sure about dynamically loaded classes, would the event content help to identify sources?)

Having said that, this event would be more useful from a runtime perspective if It would actually record execution counts and time per class. Then one can concentrate on the worst offenders, first and even use it for runtime monitoring. Is there already a finalizer profiler?

Gruss
Bernd

@mgronlun
Copy link
Author

mgronlun commented Aug 26, 2021

/label remove hotspot-jfr

@mgronlun
Copy link
Author

mgronlun commented Aug 26, 2021

/label remove core-libs

@openjdk openjdk bot removed the hotspot-jfr hotspot-jfr-dev@openjdk.org label Aug 26, 2021
@openjdk
Copy link

openjdk bot commented Aug 26, 2021

@mgronlun
The hotspot-jfr label was successfully removed.

@openjdk openjdk bot removed the core-libs core-libs-dev@openjdk.org label Aug 26, 2021
@openjdk
Copy link

openjdk bot commented Aug 26, 2021

@mgronlun
The core-libs label was successfully removed.

@mgronlun
Copy link
Author

mgronlun commented Aug 27, 2021

Sorry for the wide distribution, but this became necessary as the PR touches many component areas, if only some with minor parts. Below is a high-level description of this suggested PR.

// Design
Per class statistics about finalizers is implemented by services/finalizerService.cpp. The concept of a "service" is modelled after other management components, such as ClassLoadingService and RuntimeService.

Allocation of an object with a class overriding finalize() with a non-empty finalize() method is hooked by the runtime using bytecode "_return_register_finalizer", which has it enter InstanceKlass::register_finalizer().
A hook is added to InstanceKlass::register_finalizer() to notify the FinalizerService which increments the number of "objects_on_heap" for the corresponding InstanceKlass.

The dedicated finalizer thread is responsible for running the finalizer methods for referent objects whose java.lang.ref.Finalizers have been enqueued for finalization by the GC.
It will get a native method to report the completion state of a finalizer object back to the VM. FinalizerService will increase the total number of finalizers run and decrease the number of outstanding objects on the heap for the corresponding InstanceKlass.

Class Unloading support is in place by adding a hook in SystemDictionary::do_unloading(). The existing JFR class unloading support is extended to also report a FinalizerStatistic event for the class being unloaded before its corresponding FinalizerEntry is purged from the FinalizerService implementation table.

-Xlog:finalize is added for Unified Logging support.

// JFR event output jdk.FinalizerStatistics:
Event:jdk.FinalizerStatistics {
startTime = 14:22:06.683
finalizableClass = jdk.jfr.event.runtime.TestFinalizerStatisticsEvent$TestClassOverridingFinalize (classLoader = app)
codeSource = "file:///D:/utilities/jtreg/runtime_artifacts/work/classes/jdk/jfr/event/runtime/TestFinalizerStatisticsEvent.d/"
objects = 0
totalFinalizersRun = 2
}

Event:jdk.FinalizerStatistics {
startTime = 14:22:07.244
finalizableClass = jdk.jfr.internal.RepositoryChunk (classLoader = bootstrap)
codeSource = N/A
objects = 3
totalFinalizersRun = 0
}

// Xlog:finalizer output:
[4.517s][info][finalizer] Registered object (0x0000000073fbf594) of class jdk.jfr.internal.RepositoryChunk as finalizable
[4.737s][info][finalizer] Registered object (0x000000007ee4f130) of class jdk.jfr.event.runtime.TestFinalizerStatisticsEvent$TestClassOverridingFinalize as finalizable
[5.002s][info][finalizer] Finalizer was run for object (0x000000007ee4f130) of class jdk.jfr.event.runtime.TestFinalizerStatisticsEvent$TestClassOverridingFinalize
[5.004s][info][finalizer] Registered object (0x0000000056bf003b) of class jdk.jfr.internal.RepositoryChunk as finalizable
[5.127s][info][finalizer] Registered object (0x0000000014d51169) of class jdk.jfr.event.runtime.TestFinalizerStatisticsEvent$TestClassOverridingFinalize as finalizable
[5.325s][info][finalizer] Finalizer was run for object (0x0000000014d51169) of class jdk.jfr.event.runtime.TestFinalizerStatisticsEvent$TestClassOverridingFinalize
[5.691s][info][finalizer] Registered object (0x000000002baaa366) of class jdk.jfr.internal.RepositoryChunk as finalizable
[5.696s][info][finalizer] Registered object (0x0000000075b10e10) of class jdk.jfr.event.runtime.TestFinalizerStatisticsEvent$TestClassOverridingFinalize as finalizable
[5.891s][info][finalizer] Finalizer was run for object (0x0000000075b10e10) of class jdk.jfr.event.runtime.TestFinalizerStatisticsEvent$TestClassOverridingFinalize
[6.121s][info][finalizer] Registered object (0x000000003c036ecb) of class jdk.jfr.internal.ChunksChannel as finalizable
[6.342s][info][finalizer] Finalizer was run for object (0x000000003c036ecb) of class jdk.jfr.internal.ChunksChannel

// Misc
JfrSymbolTable - an existing JFR internal component repackaged and published to let other JFR native components re-use the symbol ids (more specifically for the CodeSource in this case).

ClassLoadingService - some parts needed to have better conditional compilation and runtime support for running the JVM when excluding JVM feature 'management'.

jmm.h - is a private interface between the JVM and the JDK, so a CSR should not be necessary for the update and version change.

// Performance
The construction of objects with non-empty finalizers is already relatively slow, in that the VM intercepts the allocation using bytecode "_return_register_finalizer", where it has to enter the VM. There, another call is made back into Java to construct a java.lang.ref.Finalizer instance. Therefore, the overhead of placing the hook in InstanceKlass::register_finalizer() is considered minimal from a performance perspective (the hook performs a lookup in a ConcurrentHashTable and a CAS).

The reporting back to the VM on finalization complete is performed only by the dedicated FinalizerThread. It introduces some additional work, but work performed by the FinalizerThread is not considered performance-sensitive because of the indeterministic nature of when finalizers are run (if at all).

// Extensibility
The data saved in FinalizerService can easily be exposed via JMX (java.lang.Management), but it is not part of this change.

The FinalizerEntry struct can also be extended, for example, with performance data.

An attempt was made to see if it was possible to attribute CPU time as well. However, the relatively short-lived character of a typical finalize() method combined with existing thread CPU timing APIs, which proved too coarse-grained (at least on some platforms?), did not give valuable data.
Another possibility could be to attribute some wall-clock time info, but it is currently unclear how useful that is. Also, the selection of what time source to use is another complexity to consider.

@openjdk
Copy link

openjdk bot commented Aug 27, 2021

@mgronlun The label hotspot-serviceabliity is not a valid label. These labels are valid:

  • serviceability
  • hotspot
  • sound
  • hotspot-compiler
  • ide-support
  • kulla
  • i18n
  • shenandoah
  • jdk
  • javadoc
  • security
  • 2d
  • swing
  • hotspot-runtime
  • jmx
  • nio
  • build
  • beans
  • core-libs
  • compiler
  • net
  • hotspot-gc
  • hotspot-jfr
  • awt

@openjdk
Copy link

openjdk bot commented Aug 27, 2021

@mgronlun The label serviceabliity is not a valid label. These labels are valid:

  • serviceability
  • hotspot
  • sound
  • hotspot-compiler
  • ide-support
  • kulla
  • i18n
  • shenandoah
  • jdk
  • javadoc
  • security
  • 2d
  • swing
  • hotspot-runtime
  • jmx
  • nio
  • build
  • beans
  • core-libs
  • compiler
  • net
  • hotspot-gc
  • hotspot-jfr
  • awt

@mgronlun
Copy link
Author

mgronlun commented Aug 27, 2021

/label add core-libs, hotspot-jfr, hotspot-runtime, serviceability

@openjdk openjdk bot added core-libs core-libs-dev@openjdk.org hotspot-jfr hotspot-jfr-dev@openjdk.org hotspot-runtime hotspot-runtime-dev@openjdk.org labels Aug 27, 2021
@openjdk
Copy link

openjdk bot commented Oct 13, 2021

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

8266936: Add a finalization JFR event

Reviewed-by: coleenp, mchung, egahlin

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 52 new commits pushed to the master branch:

  • bcbe384: 8269175: [macosx-aarch64] wrong CPU speed in hs_err file
  • 426bcee: 8275360: Use @OverRide in javax.annotation.processing
  • 4d383b9: 8275298: Remove unnecessary weak_oops_do call in adjust weak roots phase
  • fb8e5cf: 8275368: Correct statement of kinds of elements Processor.process operates over
  • d548f2f: 8274346: Support for additional content in an app-image.
  • a619f89: 8274721: UnixSystem fails to provide uid, gid or groups if no username is available
  • 1afddb2: 8275322: Change nested classes in java.management to static nested classes
  • 45ebf85: 8275333: Print count in "Too many recored phases?" assert
  • ebb1363: 8251513: Code around Parse::do_lookupswitch/do_tableswitch should be cleaned up
  • bb7dacd: 8275334: Move class loading Events to a separate section in hs_err files
  • ... and 42 more: https://git.openjdk.java.net/jdk/compare/124f82377ba93359bc59118ee315ba194080fa92...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 openjdk bot added ready Pull request is ready to be integrated and removed merge-conflict Pull request has merge conflict with target branch labels Oct 13, 2021
src/hotspot/share/jfr/support/jfrSymbolTable.cpp Outdated Show resolved Hide resolved
src/hotspot/share/jfr/support/jfrSymbolTable.hpp Outdated Show resolved Hide resolved
FinalizerEntry::FinalizerEntry(const InstanceKlass* ik) :
_ik(ik),
_objects_on_heap(0),
_total_finalizers_run(0) {}
Copy link
Contributor

@coleenp coleenp Oct 14, 2021

Choose a reason for hiding this comment

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

ok.


void FinalizerService::purge_unloaded() {
assert_locked_or_safepoint(ClassLoaderDataGraph_lock);
ClassLoaderDataGraph::classes_unloading_do(&on_unloading);
Copy link
Contributor

@coleenp coleenp Oct 14, 2021

Choose a reason for hiding this comment

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

Ok, I see - grow the table.

I'm not sure if you need to ask ik->is_loader_alive() or not, but I think you do. The InstanceKlass is removed from your table during class unloading but before that during concurrent class unloading, the class might not be alive while you look at it and concurrent class unloading hasn't gotten around to removing it yet. Since you save classes regardless of CLD, you have to check if it's alive. See classLoaderDataGraph.cpp ClassLoaderDataGraphIterator for example. The CLDG_lock only keeps the graph from not getting modified, but the classes in it might be dead.


void FinalizerService::purge_unloaded() {
assert_locked_or_safepoint(ClassLoaderDataGraph_lock);
ClassLoaderDataGraph::classes_unloading_do(&on_unloading);
Copy link
Contributor

@coleenp coleenp Oct 14, 2021

Choose a reason for hiding this comment

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

That said, I don't see where you return an InstanceKlass in the table, which would need this check. Not in class_unloading_do because this follows the _unloading list.

Copy link
Contributor

@coleenp coleenp left a comment

Thanks for doing the renames. Looks good!

@mgronlun
Copy link
Author

mgronlun commented Oct 18, 2021

Thank you for staying around with this protracted PR. Thanks @mlchung , @coleenp and @egahlin for your reviews!

@mgronlun
Copy link
Author

mgronlun commented Oct 18, 2021

/integrate

@openjdk
Copy link

openjdk bot commented Oct 18, 2021

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

  • bcbe384: 8269175: [macosx-aarch64] wrong CPU speed in hs_err file
  • 426bcee: 8275360: Use @OverRide in javax.annotation.processing
  • 4d383b9: 8275298: Remove unnecessary weak_oops_do call in adjust weak roots phase
  • fb8e5cf: 8275368: Correct statement of kinds of elements Processor.process operates over
  • d548f2f: 8274346: Support for additional content in an app-image.
  • a619f89: 8274721: UnixSystem fails to provide uid, gid or groups if no username is available
  • 1afddb2: 8275322: Change nested classes in java.management to static nested classes
  • 45ebf85: 8275333: Print count in "Too many recored phases?" assert
  • ebb1363: 8251513: Code around Parse::do_lookupswitch/do_tableswitch should be cleaned up
  • bb7dacd: 8275334: Move class loading Events to a separate section in hs_err files
  • ... and 42 more: https://git.openjdk.java.net/jdk/compare/124f82377ba93359bc59118ee315ba194080fa92...master

Your commit was automatically rebased without conflicts.

@openjdk openjdk bot closed this Oct 18, 2021
@openjdk openjdk bot added integrated Pull request has been integrated and removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels Oct 18, 2021
@openjdk
Copy link

openjdk bot commented Oct 18, 2021

@mgronlun Pushed as commit 72a976e.

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
core-libs core-libs-dev@openjdk.org hotspot-jfr hotspot-jfr-dev@openjdk.org hotspot-runtime hotspot-runtime-dev@openjdk.org integrated Pull request has been integrated serviceability serviceability-dev@openjdk.org
5 participants