8261160: Add a deserialization JFR event #2479

ChrisHegarty · 2021-02-09T12:35:27Z

This issue adds a new event to improve diagnostic information of Java deserialization. The event captures the details of deserialization activity from ObjectInputStream. The event details are similar to that of the serial filter, but is agnostic of whether a filter is installed or not. The event also captures the filter status, if there is one.

Progress

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

Issue

JDK-8261160: Add a deserialization JFR event

Reviewers

Sean Coffey (@coffeys - Reviewer)
Roger Riggs (@RogerRiggs - Reviewer)
Daniel Fuchs (@dfuch - Reviewer)
Erik Gahlin (@egahlin - Reviewer)

Contributors

Sean Coffey <coffeys@openjdk.org>
Chris Hegarty <chegar@openjdk.org>

Download

$ git fetch https://git.openjdk.java.net/jdk pull/2479/head:pull/2479
$ git checkout pull/2479

bridgekeeper · 2021-02-09T12:35:53Z

👋 Welcome back chegar! 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.

ChrisHegarty · 2021-02-09T12:36:51Z

/contributor add @coffeys

openjdk · 2021-02-09T12:37:01Z

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

core-libs
hotspot-jfr
security

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.

openjdk · 2021-02-09T12:37:10Z

@ChrisHegarty
Contributor Sean Coffey <coffeys@openjdk.org> successfully added.

ChrisHegarty · 2021-02-09T12:39:11Z

/contributor add @ChrisHegarty

openjdk · 2021-02-09T12:39:21Z

@ChrisHegarty
Contributor Chris Hegarty <chegar@openjdk.org> successfully added.

mlbridge · 2021-02-10T15:53:54Z

Webrevs

ChrisHegarty · 2021-02-10T16:06:42Z

The logging in ObjectInputStream remains conditional on whether a filter is installed, which that seems reasonable since the logging is filter specific, while the JRF event is not (but both carry effectively the same information).

The new jdk.Deserialization event uses a String to carry the filterStatus value. The value could be represented by its enum ordinal, but then the tool consuming the event would need to map that back to its string value to be meaningful.

coffeys · 2021-02-10T16:12:20Z

test/jdk/java/io/Serializable/serialFilter/GlobalFilterTest.java

@@ -48,6 +48,7 @@
 *          -Dexpected-jdk.serialFilter=java.** GlobalFilterTest
 * @run testng/othervm/policy=security.policy GlobalFilterTest
 * @run testng/othervm/policy=security.policy


You may want to add a "@requires vm.hasJFR" condition to this test

openjdk · 2021-02-10T16:14:15Z

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

8261160: Add a deserialization JFR event

Co-authored-by: Sean Coffey <coffeys@openjdk.org>
Co-authored-by: Chris Hegarty <chegar@openjdk.org>
Reviewed-by: coffeys, rriggs, dfuchs, 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 353 new commits pushed to the master branch:

6675775: 8253702: BigSur version number reported as 10.16, should be 11.nn
33fcd32: 8261659: JDK-8261027 causes a Tier1 validate-source failure
3aa1b4c: 8261623: reference to javac internals in Extern class
350303d: 8260221: java.util.Formatter throws wrong exception for mismatched flags in %% conversion
6475d47: 8261655: [PPC64] Build broken after JDK-8260941
c0e805a: 8261654: Missing license header in Signatures.java
b670efd: 8261072: AArch64: Fix MacroAssembler::get_thread convention
59b8d59: 8261481: Cannot read Kerberos settings in dynamic store on macOS Big Sur
9f81ca8: 8261230: GC tracing of page sizes are wrong in a few places
40ae993: 8261027: AArch64: Support for LSE atomics C++ HotSpot code
... and 343 more: https://git.openjdk.java.net/jdk/compare/0785147460934ee2aa413ab7872837094824bd3d...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.

dfuch · 2021-02-10T20:53:12Z

src/jdk.jfr/share/classes/jdk/jfr/events/DeserializationEvent.java

+import jdk.jfr.internal.MirrorEvent;
+
+@Category({"Java Development Kit", "Serialization"})
+@Label("Deserialization events")


This seems to differ from the format of other event labels defined in this package, e.g:

@Label("Process Start") @Label("File Read") ...

What would you think of changing it to one of:

@Label("Deserialization") @Label("Deserialized Object")

egahlin · 2021-02-11T06:46:49Z

src/java.base/share/classes/java/io/ObjectInputStream.java

+        }
+        DeserializationEvent event = new DeserializationEvent();
+        if (event.shouldCommit()) {
+            event.filterStatus = status == null ? "n/a" : status.name();


We use null for missing value, so no need to have "n/a"

egahlin · 2021-02-11T06:48:26Z

src/java.base/share/classes/java/io/ObjectInputStream.java

+            event.totalObjectRefs = totalObjectRefs;
+            event.depth = depth;
+            event.bytesRead = bytesRead;
+            event.exception = Objects.toString(ex, "n/a");


You may want to change the name of the field to "exceptionMessage" to make it clear it's the message, not the class.

egahlin · 2021-02-11T06:49:57Z

src/jdk.jfr/share/classes/jdk/jfr/events/DeserializationEvent.java

+    public String filterStatus;
+
+    @Label ("Class")
+    public String clazz;


We typically use "type" when referring to a class (instead of clazz), or we prefix it, i.e exceptionClass

egahlin · 2021-02-11T06:50:30Z

src/jdk.jfr/share/classes/jdk/jfr/events/DeserializationEvent.java

+    public String filterStatus;
+
+    @Label ("Class")
+    public String clazz;


Is it possible to make the field of type Class?

egahlin · 2021-02-11T06:55:09Z

src/jdk.jfr/share/classes/jdk/jfr/events/DeserializationEvent.java

+    public int arrayLength;
+
+    @Label ("Reference count")
+    public long totalObjectRefs;


"Reference count" sounds a bit like resource counter? Is that the case? If not, perhaps "Object References" is better. We try to avoid abbreviations. How about naming the field "totalObjectReferences" or just "objectReferences"?

RogerRiggs · 2021-02-11T14:27:19Z

As proposed, events are only created if there is a serialFilter in effect (and enabled by JFR configuration).
Being able to create the events without a serialFilter in effect would be useful for monitoring, especially if it could be controlled by a separate JFR configuration option. (always, never, serial-filter , etc.)

ChrisHegarty · 2021-02-11T15:05:43Z

I updated the PR and addressed all comments so far. Specifically:

@RogerRiggs The generation of the event is independent of whether the filter is set or not. I also added a piece of state to determine if a filter is set or not. I think it could be useful to analyse all Deserialisation events to, say, ensure that there are none operating without a filter ( and the filterStatus state is ambitious in the null case ).

@coffeys I would like GlobalFilterTest to run regardless of whether or not the jfr module is present, but of course running the test with jfr enabled is desirable too, so I added a separate at test tag for that case.

@egahlin Excellent suggestions on the naming, etc. I adopted all. And added a test to ensure that the creation and generation of the event does not inadvertently trigger class initialization if the filter rejects the attempt ( thanks @dfuch )

@dfuch Thanks for the improved label suggestion, it is now merged in.

dfuch · 2021-02-11T15:45:33Z

src/jdk.jfr/share/classes/jdk/jfr/events/DeserializationEvent.java

+    @Label("Filter configured")
+    public boolean filterConfigured;


Should that be "Filter Configured" for consistency?

Good catch. Fixed.

dfuch

LGTM

ChrisHegarty · 2021-02-12T16:22:36Z

Speaking to Erik offline, he suggested to split the exceptionMessage into exceptionType and exceptionMessage ( since the code was somewhat overloading the existing Sting field by using toString to force the exception class name and message into a single sting ). While the exceptionXXX field should rarely be non-null, they add very little overhead.

ChrisHegarty · 2021-02-12T17:34:35Z

/integrate

openjdk · 2021-02-12T17:35:48Z

@ChrisHegarty Since your change was applied there have been 355 commits pushed to the master branch:

a305743: 8261660: AArch64: Race condition in stub code generation for LSE Atomics
28163a9: 8261652: Remove some dead comments from os_bsd_x86
6675775: 8253702: BigSur version number reported as 10.16, should be 11.nn
33fcd32: 8261659: JDK-8261027 causes a Tier1 validate-source failure
3aa1b4c: 8261623: reference to javac internals in Extern class
350303d: 8260221: java.util.Formatter throws wrong exception for mismatched flags in %% conversion
6475d47: 8261655: [PPC64] Build broken after JDK-8260941
c0e805a: 8261654: Missing license header in Signatures.java
b670efd: 8261072: AArch64: Fix MacroAssembler::get_thread convention
59b8d59: 8261481: Cannot read Kerberos settings in dynamic store on macOS Big Sur
... and 345 more: https://git.openjdk.java.net/jdk/compare/0785147460934ee2aa413ab7872837094824bd3d...master

Your commit was automatically rebased without conflicts.

Pushed as commit 3dc6f52.

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

coffeys and others added 3 commits January 21, 2021 15:17

commit 1

25a06ee

commit 2

68eb5dd

Unconditionally fire a deser event regardless of filter, and add test

fb7941c

openjdk bot added security security-dev@openjdk.org core-libs core-libs-dev@openjdk.org hotspot-jfr hotspot-jfr-dev@openjdk.org labels Feb 9, 2021

minor cleanup; all tests passing

ca0bcf4

ChrisHegarty marked this pull request as ready for review February 10, 2021 15:50

openjdk bot added the rfr Pull request is ready for review label Feb 10, 2021

coffeys approved these changes Feb 10, 2021

View reviewed changes

openjdk bot added the ready Pull request is ready to be integrated label Feb 10, 2021

RogerRiggs approved these changes Feb 10, 2021

View reviewed changes

dfuch reviewed Feb 10, 2021

View reviewed changes

egahlin reviewed Feb 11, 2021

View reviewed changes

Review comments

8ecf63c

Fix failing test

5737ee7

coffeys approved these changes Feb 11, 2021

View reviewed changes

dfuch reviewed Feb 11, 2021

View reviewed changes

Filter **C**onfigured

d764f75

dfuch approved these changes Feb 11, 2021

View reviewed changes

RogerRiggs approved these changes Feb 11, 2021

View reviewed changes

Split exception into type and message

8cb8f75

RogerRiggs approved these changes Feb 12, 2021

View reviewed changes

coffeys approved these changes Feb 12, 2021

View reviewed changes

dfuch approved these changes Feb 12, 2021

View reviewed changes

egahlin approved these changes Feb 12, 2021

View reviewed changes

openjdk bot closed this Feb 12, 2021

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 Feb 12, 2021

LongyuZhang mentioned this pull request Mar 11, 2021

JDK17 jdk_io_0_FAILED - Error evaluating expression: invalid boolean value: null' for expression vm.hasJFR' eclipse-openj9/openj9#12079

Closed

8261160: Add a deserialization JFR event #2479

8261160: Add a deserialization JFR event #2479

ChrisHegarty commented Feb 9, 2021 •

edited by openjdk bot

bridgekeeper bot commented Feb 9, 2021

ChrisHegarty commented Feb 9, 2021

openjdk bot commented Feb 9, 2021

openjdk bot commented Feb 9, 2021

ChrisHegarty commented Feb 9, 2021

openjdk bot commented Feb 9, 2021

mlbridge bot commented Feb 10, 2021 •

edited

ChrisHegarty commented Feb 10, 2021

coffeys Feb 10, 2021

openjdk bot commented Feb 10, 2021 •

edited

dfuch Feb 10, 2021

egahlin Feb 11, 2021

egahlin Feb 11, 2021

egahlin Feb 11, 2021 •

edited

egahlin Feb 11, 2021

egahlin Feb 11, 2021 •

edited

RogerRiggs commented Feb 11, 2021

ChrisHegarty commented Feb 11, 2021

dfuch Feb 11, 2021

ChrisHegarty Feb 11, 2021

dfuch left a comment

ChrisHegarty commented Feb 12, 2021

ChrisHegarty commented Feb 12, 2021

openjdk bot commented Feb 12, 2021

8261160: Add a deserialization JFR event #2479

8261160: Add a deserialization JFR event #2479

Conversation

ChrisHegarty commented Feb 9, 2021 • edited by openjdk bot

Progress

Issue

Reviewers

Contributors

Download

bridgekeeper bot commented Feb 9, 2021

ChrisHegarty commented Feb 9, 2021

openjdk bot commented Feb 9, 2021

openjdk bot commented Feb 9, 2021

ChrisHegarty commented Feb 9, 2021

openjdk bot commented Feb 9, 2021

mlbridge bot commented Feb 10, 2021 • edited

Webrevs

ChrisHegarty commented Feb 10, 2021

coffeys Feb 10, 2021

Choose a reason for hiding this comment

openjdk bot commented Feb 10, 2021 • edited

dfuch Feb 10, 2021

Choose a reason for hiding this comment

egahlin Feb 11, 2021

Choose a reason for hiding this comment

egahlin Feb 11, 2021

Choose a reason for hiding this comment

egahlin Feb 11, 2021 • edited

Choose a reason for hiding this comment

egahlin Feb 11, 2021

Choose a reason for hiding this comment

egahlin Feb 11, 2021 • edited

Choose a reason for hiding this comment

RogerRiggs commented Feb 11, 2021

ChrisHegarty commented Feb 11, 2021

dfuch Feb 11, 2021

Choose a reason for hiding this comment

ChrisHegarty Feb 11, 2021

Choose a reason for hiding this comment

dfuch left a comment

Choose a reason for hiding this comment

ChrisHegarty commented Feb 12, 2021

ChrisHegarty commented Feb 12, 2021

openjdk bot commented Feb 12, 2021

ChrisHegarty commented Feb 9, 2021 •

edited by openjdk bot

mlbridge bot commented Feb 10, 2021 •

edited

openjdk bot commented Feb 10, 2021 •

edited

egahlin Feb 11, 2021 •

edited

egahlin Feb 11, 2021 •

edited