RFR: 8264768: JFR: Allow events to be printed to the log

[Erik Gahlin]

Hi,

Could I have a review of change that allow events to be printed to the log. 

This feature is meant for debugging purposes and to simplify development of new events, both user-defined and JDK events. It's not suitable for production environments because 1) The amount of data that will printed in the default configuration 2) The overhead of formatting the output 3) Events may contain sensitive information that should not end up in a log file.

To print only user-defined events to standard out:
$  java -Xlog:jfr+event=debug -XX:StartFlightRecording ...

To print only JDK events to standard out:
$  java -Xlog:jfr+event+system=debug -XX:StartFlightRecording ...

To print both user-defined and JDK events to standard out:
$  java -Xlog:jfr+event*=debug -XX:StartFlightRecording ...

To print more than five frames in a stack trace:
$  java -Xlog:jfr+event*=trace -XX:StartFlightRecording ...

To print all events to standard out without decoration, similar to 'jfr print'
$  java -Xlog:jfr+event*=debug::none -XX:StartFlightRecording ...

Example outputs of -Xlog:jfr+event*=debug:

[2.444s][debug][jfr,system,event] jdk.CPULoad {
[2.444s][debug][jfr,system,event]   startTime = 15:32:09.605
[2.444s][debug][jfr,system,event]   jvmUser = 8,27%
[2.444s][debug][jfr,system,event]   jvmSystem = 0,68%
[2.444s][debug][jfr,system,event]   machineTotal = 12,78%
[2.444s][debug][jfr,system,event] }

[7.352s][debug][jfr,event       ] testing.FooBarBaz {
[7.352s][debug][jfr,event       ]   startTime = 15:33:11.526
[7.352s][debug][jfr,event       ]   duration = 1,00 s
[7.352s][debug][jfr,event       ]   eventThread = "main" (javaThreadId = 1)
[7.352s][debug][jfr,event       ]   stackTrace = [
[7.352s][debug][jfr,event       ]     Test.method3() line: 32
[7.352s][debug][jfr,event       ]     Test.method2() line: 24
[7.352s][debug][jfr,event       ]     Test.method1() line: 20
[7.352s][debug][jfr,event       ]     Test.main(String[]) line: 15
[7.352s][debug][jfr,event       ]     jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Method, Object, Object[])
[7.352s][debug][jfr,event       ]     ...
[7.352s][debug][jfr,event       ]   ]
[7.352s][debug][jfr,event       ] }

There is no good way to do filtering per event, since log tags needs to be known at compile time and JFR allows user-defined events to be registered at runtime. Maybe something can be invented that allows UL to accept some JFR specific syntax, i.e. -Xlog:jfr[jdk.ConcurrentModeFailure,jdk.AllocationRequiringGC], but it's outside the scope of this enhancement request. 

A custom .jfc file can always be created for the events you want to record, i.e. -Xlog:jfr+event*=debug -XX:StartFlightRecording:settings=custom.jfc

Testing: jdk/jdk/jfr

Thanks
Erik

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

Commit messages:
 - Add missing includes
 - Bypass JNI
 - Initial

Changes: https://git.openjdk.java.net/jdk/pull/3377/files
 Webrev: https://webrevs.openjdk.java.net/?repo=jdk&pr=3377&range=00
  Issue: https://bugs.openjdk.java.net/browse/JDK-8264768
  Stats: 1035 lines in 29 files changed: 1004 ins; 7 del; 24 mod
  Patch: https://git.openjdk.java.net/jdk/pull/3377.diff
  Fetch: git fetch https://git.openjdk.java.net/jdk pull/3377/head:pull/3377

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