8356968: JFR: Compilation event should be enabled for all compilations by default

[shipilev]

In the field, we are using -XX:+PrintCompilation to track compiler performance. Alternatively, -Xlog:jit* prints the same. JFR has a the related jdk.Compilation event that gives us even richer diagnostics. Yet, that event is set at a very high threshold (1000ms), which skips almost all compilations! This threshold is set to such a high value from the beginning.

It is fairly normal to have lots of compilations in 100+ ms range individually, and their sum impact is what we are after. Also, the compilations are normally quite rare, and there are a couple of thousands of compiles in most workloads, and they only happen sporadically. This means, the event count without any threshold is not high.

Therefore, it would be convenient to make sure that basic Compilation event is enabled unconditionally, e.g. by dropping the default threshold to 0.

See more logs in the bug itself.

Additional testing:

• Ad-hoc tests with printing compilation events
• Linux x86_64 server fastdebug, jdk_jfr

---

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-8356968: JFR: Compilation event should be enabled for all compilations by default (Enhancement - P4)

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 25247

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

Using diff file

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

Using Webrev

Link to Webrev Comment

[bridgekeeper]

👋 Welcome back shade! 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]

❗ This change is not yet ready to be integrated.
See the Progress checklist in the description for automated requirements.

[openjdk]

@shipilev 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]

Webrevs

• 00: Full (dae17802)

[egahlin]

The overhead of the event is low, I believe, but I think the concern was that too many events were generated with little value to the end user. The buffers will be filled, and other, more important events will be pushed out. That said, there are probably other JVM events, i.e., low-level GC or runtime events, that are on by default, which may be less interesting than the compilation event.

jfr summary lists the number of events and how much space they take up.

Maybe we should reprioritize them?

[shipilev]

The overhead of the event is low, I believe, but I think the concern was that too many events were generated with little value to the end user.

I can see that. But the neat part about compilation events is that we are supposed to have a limited number of them. As system goes into steady state, compilations are supposed to become very rare. And if they are not, that is actually a signal something is really off, and we do want to know :)

jfr summary lists the number of events and how much space they take up.

I think current overheads are fair.

For example, on javac HelloWorld workload, jdk.Compilation is about 1K events, about 25K in total (~ 25 bytes/event), on-par with system process, flags, settings events. Takes ~7% of the dump on javac Hello World, and that is likely a high estimate, as longer apps would likely start dumping much more non-compilation events. Sounds to me doing a ThreadDump 3 times already takes more space than the sum total of compilation events.

 $ ls -lah comp.jfr
-rw-rw-r-- 1 shade shade 365K May 14 14:00 comp.jfr

$ jfr summary comp.jfr | sort -k 3 -n -r | head -n 10
 jdk.CheckPoint                             14        134299
 jdk.Metadata                                1        107126
 jdk.SystemProcess                         546         32949
 jdk.Compilation                           946         23678
 jdk.ThreadDump                              2         18679
 jdk.BooleanFlag                           492         14607
 jdk.ActiveSetting                         356          8846
 jdk.ModuleExport                          504          5414
 jdk.LongFlag                              136          4237
 jdk.InitialEnvironmentVariable             73          3077
...

[shipilev]

@egahlin -- does summary analysis alleviate your concern about event overheads?

[egahlin]

@egahlin -- does summary analysis alleviate your concern about event overheads?

No, some applications load new classes all the time. This is why we have the Class Load event turned off by default as well. We have over 150 events, so the budget per event is small.

[shipilev]

I think @iwanowww had an opinion on this :)

[bridgekeeper]

@shipilev This pull request has been inactive for more than 4 weeks and will be automatically closed if another 4 weeks passes without any activity. To avoid this, simply issue a /touch or /keepalive command to the pull request. Feel free to ask for assistance if you need help with progressing this pull request towards integration!

[shipilev]

/touch

[openjdk]

@shipilev The pull request is being re-evaluated and the inactivity timeout has been reset.

[bridgekeeper]

@shipilev This pull request has been inactive for more than 4 weeks and will be automatically closed if another 4 weeks passes without any activity. To avoid this, simply issue a /touch or /keepalive command to the pull request. Feel free to ask for assistance if you need help with progressing this pull request towards integration!

[shipilev]

/touch

[openjdk]

@shipilev The pull request is being re-evaluated and the inactivity timeout has been reset.

[bridgekeeper]

@shipilev This pull request has been inactive for more than 4 weeks and will be automatically closed if another 4 weeks passes without any activity. To avoid this, simply issue a /touch or /keepalive command to the pull request. Feel free to ask for assistance if you need help with progressing this pull request towards integration!

[shipilev]

/touch

[shipilev]

I still believe this is a right idea, BTW :)

[openjdk]

@shipilev The pull request is being re-evaluated and the inactivity timeout has been reset.

[egahlin]

jfr summary doesn't show the full cost of an event. The jdk.CheckPoint event also constains information about methods, classes and class loaders that the jdk.Compilation events hold references to. If you want to see the full cost:

$ java -Xcomp -XX:StartFlightRecording:jdk.Compilation#threshold=0ns,filename=recording.jfr
  -jar ./build/platform/images/jdk/demo/jfc/J2Ddemo/J2Ddemo.jar`
$ jfr scrub recording.jfr waste-free.jfr
$ jfr scrub --exclude-events jdk.Compilation waste-free.jfr no-compilation.jfr
$ ls -l waste-free.jfr no-compilation.jfr
-rw-r--r--  1 -----  -----  2054496 Aug 27 17:29 waste-free.jfr
-rw-r--r--  1 -----  -----   895963 Aug 27 17:32 no-compilation.jfr

[bridgekeeper]

@shipilev This pull request has been inactive for more than 4 weeks and will be automatically closed if another 4 weeks passes without any activity. To avoid this, simply issue a /touch or /keepalive command to the pull request. Feel free to ask for assistance if you need help with progressing this pull request towards integration!