8284686: Interval of < 1 ms disables ExecutionSample events #8183

parttimenerd · 2022-04-11T16:53:08Z

Fixes the issue by rounding the period interval to the next full millisecond larger than zero.

The following from the bug report works now:

java -XX:StartFlightRecording=filename=flight.jfr,jdk.ExecutionSample#period=999us CLASS_FILE; jfr print --events jdk.ExecutionSample flight.jfr

It considers the period to be 1ms, producing the recording as expected.

Progress

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

Issue

JDK-8284686: Interval of < 1 ms disables ExecutionSample events

Reviewers

Erik Gahlin (@egahlin - Reviewer)

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 8183

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

Using diff file

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

bridgekeeper · 2022-04-11T16:53:29Z

👋 Welcome back parttimenerd! 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 · 2022-04-11T16:55:48Z

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

mlbridge · 2022-04-11T16:59:06Z

Webrevs

parttimenerd · 2022-04-12T13:10:18Z

The failing test seems to fail spuriously on Mac aarch64 (https://bugs.openjdk.java.net/browse/JDK-8284144). It does not have any relation to the proposed changes (it should not even call the changed code as JFR is not used).

src/jdk.jfr/share/classes/jdk/jfr/internal/settings/PeriodSetting.java

egahlin · 2022-04-13T12:45:15Z

You mentioned elsewhere that it fails in debug mode, I think it should work there as well.

Did you try your change with tests in test/jdk/jdk/jfr? Might make sense to write a test, or add your use case to an existing test.

The documentation should say "1 ms" instead of "1ms". The latter is only used at command-line.

You are changing the specification, so a CSR might be needed as well.

parttimenerd · 2022-04-13T13:36:08Z

I added a small test case, hopefully it works.

parttimenerd · 2022-04-28T09:24:47Z

@egahlin is my PR fine?

egahlin · 2022-04-28T10:44:36Z

@egahlin is my PR fine?

I discussed this with Markus and we're leaning towards not mentioning it in the documentation and instead keep it as an implementation detail. All settings are a best effort, not just the period, as it depends OS, hardware etc. so the error could in practise be magnitudes more than a ms.

In the test, could you check the behaviour instead of using internal classes.

Perhaps something like this. I have not tested the code.

package jdk.jfr.api.recording.event;

import java.time.Duration;
import jdk.jfr.Event;
import jdk.jfr.FlightRecorder;
import jdk.jfr.consumer.RecordingStream;

/**
 * @test Tests that periodic events are not disabled when using a very short
 *       period
 * @key jfr
 * @requires vm.hasJFR
 * @library /test/lib /test/jdk
 * @run main/othervm jdk.jfr.api.recording.event.TestShortPeriod
 */
public class TestShortPeriod {

    static class PeriodicEvent extends Event {
    }

    public static void main(String... args) {
        testNativeEventPeriod();
        testJavaEventPeriod();
        testExecutionSamplePeriod();
    }

    private static void testNativeEventPeriod() {
        try (var r = new RecordingStream()) {
            r.enable(EventNames.JVMInformation).withPeriod(Duration.ofNanos(1));
            r.onEvent(e -> r.close());
            r.start();
        }
    }

    private static void testJavaEventPeriod() {
        Runnable hook = () -> {
            PeriodicEvent e = new PeriodicEvent();
            e.commit();
        };
        FlightRecorder.addPeriodicEvent(PeriodicEvent.class, hook);
        try (var r = new RecordingStream()) {
            r.enable(PeriodicEvent.class).withPeriod(Duration.ofNanos(1));
            r.onEvent(e -> r.close());
            r.start();
        }
        FlightRecorder.removePeriodicEvent(hook);
    }

    // The execution sample event doesn't use the standard mechanism
    // for periodic events
    private static void testExecutionSamplePeriod() {
        try (var r = new RecordingStream()) {
            r.enable(EventNames.ExecutionSample).withPeriod(Duration.ofNanos(1));
            r.onEvent(e -> r.close());
            r.start();
        }
    }
}

parttimenerd · 2022-04-28T10:50:19Z

Then I close the CSR too?

egahlin · 2022-04-28T10:55:17Z

Then I close the CSR too?

Yes.

/csr unneeded

openjdk · 2022-04-28T10:56:32Z

@egahlin The CSR requirement cannot be removed as there is already a CSR associated with the main issue of this pull request. Please withdraw the CSR JDK-8284824 and then use the command /csr unneeded again.

openjdk · 2022-04-28T11:20:10Z

@parttimenerd only Reviewers can determine that a CSR is not needed.

parttimenerd · 2022-04-28T11:22:35Z

Perhaps something like this. I have not tested the code.

What do you want to test with this?

A far simpler test could be to just check that after calling .withPeriod(Duration.ofNanos(1)) sample events are still enabled.

egahlin · 2022-04-28T12:04:45Z

Perhaps something like this. I have not tested the code.

What do you want to test with this?

A far simpler test could be to just check that after calling .withPeriod(Duration.ofNanos(1)) sample events are still enabled.

I want to test that events are emitted. A check of EventType::isEnabled could return true, but events still not being recorded.

parttimenerd · 2022-04-28T12:08:58Z

But where do you test it? Or more generally: How can I write a test that runs JFR? Should this test run a small loop 100ms and then check that there are > 0 events recorded?

egahlin · 2022-04-28T12:42:06Z

But where do you test it? Or more generally: How can I write a test that runs JFR? Should this test run a small loop 100ms and then check that there are > 0 events recorded?

The test code above will run JFR until an event is emitted (RecordingStream::start() is blocking)

If there is a bug, the test will hang with a stack trace indicating which test method that failed.

parttimenerd · 2022-04-28T12:44:27Z

Thanks for your explanation.

egahlin · 2022-04-28T13:15:06Z

/csr unneeded

openjdk · 2022-04-28T13:16:28Z

@egahlin determined that a CSR request is not needed for this pull request.

This reverts commit fe7d711.

parttimenerd · 2022-05-05T08:46:45Z

I'm currently struggling with writing the tests as there are problems, even with durations > 1ms and on the stock JVM.

test/jdk/jdk/jfr/api/recording/event/TestShortPeriod.java

openjdk · 2022-05-09T18:23:34Z

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

8284686: Interval of < 1 ms disables ExecutionSample events

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

6a7c023: 8284316: Support accessibility ManualTestFrame.java for non SwingSet tests
40470d8: 8284550: test failure_handler is not properly invoking jhsdb jstack, resulting in failure to produce a stack when a test times out
837928b: 8222323: ChildAlwaysOnTopTest.java fails with "RuntimeException: Failed to unset alwaysOnTop"
397d095: 8285743: Ensure each IntegerPolynomial object is only created once
29ccb8f: 8285914: AppCDS crash when using shared archive with old class file
fe6e0c0: 8286371: Avoid use of deprecated str[n]icmp
97a9835: 8274517: java/util/DoubleStreamSums/CompensatedSums.java fails with expected [true] but found [false]
034f20f: 8212136: Remove finalizer implementation in SSLSocketImpl
36e4df9: 8285516: clearPassword should be called in a finally try block
b849efd: 8285923: [REDO] JDK-8285802 AArch64: Consistently handle offsets in MacroAssembler as 64-bit quantities
... and 352 more: https://git.openjdk.java.net/jdk/compare/523899e36c543343283ab0b1f5cfcba805e7b918...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.

As you do not have Committer status in this project an existing Committer must agree to sponsor your change. Possible candidates are the reviewers of this PR (@egahlin) but any other Committer may sponsor as well.

➡️ To flag this PR as ready for integration with the above commit message, type /integrate in a new comment. (Afterwards, your sponsor types /sponsor in a new comment to perform the integration).

parttimenerd · 2022-05-09T19:18:46Z

/integrate

openjdk · 2022-05-09T19:20:25Z

@parttimenerd
Your change (at version eda5942) is now ready to be sponsored by a Committer.

egahlin · 2022-05-09T19:26:06Z

/sponsor

openjdk · 2022-05-09T19:27:47Z

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

02e5fc0: 8286435: JDK-8284316 caused validate-source to fail in Tier1
6a7c023: 8284316: Support accessibility ManualTestFrame.java for non SwingSet tests
40470d8: 8284550: test failure_handler is not properly invoking jhsdb jstack, resulting in failure to produce a stack when a test times out
837928b: 8222323: ChildAlwaysOnTopTest.java fails with "RuntimeException: Failed to unset alwaysOnTop"
397d095: 8285743: Ensure each IntegerPolynomial object is only created once
29ccb8f: 8285914: AppCDS crash when using shared archive with old class file
fe6e0c0: 8286371: Avoid use of deprecated str[n]icmp
97a9835: 8274517: java/util/DoubleStreamSums/CompensatedSums.java fails with expected [true] but found [false]
034f20f: 8212136: Remove finalizer implementation in SSLSocketImpl
36e4df9: 8285516: clearPassword should be called in a finally try block
... and 353 more: https://git.openjdk.java.net/jdk/compare/523899e36c543343283ab0b1f5cfcba805e7b918...master

Your commit was automatically rebased without conflicts.

openjdk · 2022-05-09T19:28:06Z

@egahlin @parttimenerd Pushed as commit 902b1dd.

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

8284686: Interval of < 1 ms disables ExecutionSample events

f678d1e

openjdk bot added the rfr Pull request is ready for review label Apr 11, 2022

openjdk bot added the hotspot-jfr hotspot-jfr-dev@openjdk.org label Apr 11, 2022

jbachorik reviewed Apr 13, 2022

View reviewed changes

src/jdk.jfr/share/classes/jdk/jfr/internal/settings/PeriodSetting.java Outdated Show resolved Hide resolved

Fix description and zero case

cc7de79

openjdk bot added the csr Pull request needs approved CSR before integration label Apr 13, 2022

Try to add small test case

a2c1067

openjdk bot removed the csr Pull request needs approved CSR before integration label Apr 28, 2022

parttimenerd added 2 commits April 29, 2022 13:02

Remove Thread from make_walkable signature

fe7d711

Revert "Remove Thread from make_walkable signature"

a9aebe0

This reverts commit fe7d711.

parttimenerd added 2 commits May 5, 2022 12:20

Remove TestPeriodSetting

dda1242

Add TestShortPeriod

e5b7f55

jbachorik reviewed May 5, 2022

View reviewed changes

test/jdk/jdk/jfr/api/recording/event/TestShortPeriod.java Show resolved Hide resolved

RealCLanger reviewed May 6, 2022

View reviewed changes

test/jdk/jdk/jfr/api/recording/event/TestShortPeriod.java Outdated Show resolved Hide resolved

Update documentation

eda5942

egahlin approved these changes May 9, 2022

View reviewed changes

openjdk bot added the ready Pull request is ready to be integrated label May 9, 2022

openjdk bot added the sponsor Pull request is ready to be sponsored label May 9, 2022

openjdk bot added the integrated Pull request has been integrated label May 9, 2022

openjdk bot closed this May 9, 2022

openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review sponsor Pull request is ready to be sponsored labels May 9, 2022

8284686: Interval of < 1 ms disables ExecutionSample events #8183

8284686: Interval of < 1 ms disables ExecutionSample events #8183

Uh oh!

Conversation

parttimenerd commented Apr 11, 2022 • edited by openjdk bot Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Progress

Issue

Reviewers

Reviewing

Uh oh!

bridgekeeper bot commented Apr 11, 2022

Uh oh!

openjdk bot commented Apr 11, 2022

Uh oh!

mlbridge bot commented Apr 11, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Webrevs

Uh oh!

parttimenerd commented Apr 12, 2022

Uh oh!

Uh oh!

egahlin commented Apr 13, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

parttimenerd commented Apr 13, 2022

Uh oh!

parttimenerd commented Apr 28, 2022

Uh oh!

egahlin commented Apr 28, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

parttimenerd commented Apr 28, 2022

Uh oh!

egahlin commented Apr 28, 2022

Uh oh!

openjdk bot commented Apr 28, 2022

Uh oh!

openjdk bot commented Apr 28, 2022

Uh oh!

parttimenerd commented Apr 28, 2022

Uh oh!

egahlin commented Apr 28, 2022

Uh oh!

parttimenerd commented Apr 28, 2022

Uh oh!

egahlin commented Apr 28, 2022

Uh oh!

parttimenerd commented Apr 28, 2022

Uh oh!

egahlin commented Apr 28, 2022

Uh oh!

openjdk bot commented Apr 28, 2022

Uh oh!

parttimenerd commented May 5, 2022

Uh oh!

Uh oh!

Uh oh!

openjdk bot commented May 9, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

parttimenerd commented May 9, 2022

Uh oh!

openjdk bot commented May 9, 2022

Uh oh!

egahlin commented May 9, 2022

Uh oh!

openjdk bot commented May 9, 2022

Uh oh!

openjdk bot commented May 9, 2022

Uh oh!

Reviewers

Assignees

Labels

Milestone

Development

Uh oh!

4 participants

parttimenerd commented Apr 11, 2022 •

edited by openjdk bot

Loading

mlbridge bot commented Apr 11, 2022 •

edited

Loading

egahlin commented Apr 13, 2022 •

edited

Loading

egahlin commented Apr 28, 2022 •

edited

Loading

openjdk bot commented May 9, 2022 •

edited

Loading