8358590: JFR: Include min and max in MethodTiming event

Reviewed-by: mgronlun
This commit is contained in:
Erik Gahlin 2025-06-05 11:42:31 +00:00
parent eb770a060a
commit 6cdfd36ac8
6 changed files with 49 additions and 7 deletions

View File

@ -1315,7 +1315,9 @@
<Event name="MethodTiming" category="Java Application" label="Method Timing" thread="false" stackTrace="false" startTime="false" period="everyChunk"> <Event name="MethodTiming" category="Java Application" label="Method Timing" thread="false" stackTrace="false" startTime="false" period="everyChunk">
<Field type="Method" name="method" label="Method" /> <Field type="Method" name="method" label="Method" />
<Field type="long" name="invocations" label="Invocations" description="The number of times the method was invoked" /> <Field type="long" name="invocations" label="Invocations" description="The number of times the method was invoked" />
<Field type="Tickspan" name="average" label="Average" description="An approximation of the wall-clock time it took for the method to execute" /> <Field type="Tickspan" name="minimum" label="Minimum" description="An approximation of the minimum wall-clock time it took for the method to execute" />
<Field type="Tickspan" name="average" label="Average" description="An approximation of the average wall-clock time it took for the method to execute" />
<Field type="Tickspan" name="maximum" label="Maximum" description="An approximation of the maximum wall-clock time it took for the method to execute" />
</Event> </Event>
<Type name="DeoptimizationReason" label="Deoptimization Reason"> <Type name="DeoptimizationReason" label="Deoptimization Reason">

View File

@ -42,11 +42,19 @@ public final class MethodTimingEvent extends AbstractJDKEvent {
@Label("Invocations") @Label("Invocations")
public long invocations; public long invocations;
@Label("Minimum Time")
@Timespan(Timespan.TICKS)
public long minimum;
@Label("Average Time") @Label("Average Time")
@Timespan(Timespan.TICKS) @Timespan(Timespan.TICKS)
public long average; public long average;
public static void commit(long start, long method, long invocations, long average) { @Label("Maximum Time")
@Timespan(Timespan.TICKS)
public long maximum;
public static void commit(long start, long method, long invocations, long minimum, long average, long maximum) {
// Generated by JFR // Generated by JFR
} }

View File

@ -471,9 +471,9 @@ table = "COLUMN 'Alloc. Time', 'Application Method', 'Object Age', 'Heap Usage'
[application.method-timing] [application.method-timing]
label = "Method Timing" label = "Method Timing"
table = "COLUMN 'Timed Method', 'Invocations', 'Average Time' table = "COLUMN 'Timed Method', 'Invocations', 'Min. Tim', 'Max. Time', 'Average Time'
FORMAT none, none, ms-precision:6 FORMAT none, none, ms-precision:6
SELECT LAST_BATCH(method) AS M, LAST_BATCH(invocations), LAST_BATCH(average) SELECT LAST_BATCH(method) AS M, LAST_BATCH(invocations), LAST_BATCH(minimum), LAST_BATCH(maximum), LAST_BATCH(average)
FROM jdk.MethodTiming GROUP BY method ORDER BY average" FROM jdk.MethodTiming GROUP BY method ORDER BY average"
[application.method-calls] [application.method-calls]

View File

@ -146,6 +146,7 @@ public final class PlatformTracer {
public static void addObjectTiming(long duration) { public static void addObjectTiming(long duration) {
OBJECT.invocations().getAndIncrement(); OBJECT.invocations().getAndIncrement();
OBJECT.time().addAndGet(duration); OBJECT.time().addAndGet(duration);
OBJECT.updateMinMax(duration);
} }
public static void addTiming(long id, long duration) { public static void addTiming(long id, long duration) {
@ -153,6 +154,7 @@ public final class PlatformTracer {
if (entry != null) { if (entry != null) {
entry.invocations().getAndIncrement(); entry.invocations().getAndIncrement();
entry.time().addAndGet(duration); entry.time().addAndGet(duration);
entry.updateMinMax(duration);
} }
} }

View File

@ -61,7 +61,12 @@ public final class TimedClass {
long invocations = tm.invocations().get(); long invocations = tm.invocations().get();
long time = tm.time().get(); long time = tm.time().get();
long average = invocations == 0 ? Long.MIN_VALUE : time / invocations; long average = invocations == 0 ? Long.MIN_VALUE : time / invocations;
MethodTimingEvent.commit(timestamp, methodId, invocations, average); long min = tm.minimum().get();
if (min == Long.MAX_VALUE) {
min = Long.MIN_VALUE; // Signals that the value is missing
}
long max = tm.maximum().get();
MethodTimingEvent.commit(timestamp, methodId, invocations, min, average, max);
tm.method().log("Emitted event"); tm.method().log("Emitted event");
} }
} }

View File

@ -33,8 +33,33 @@ import java.util.concurrent.atomic.AtomicLong;
* <p> * <p>
* Fields in record classes are truly final so might help to have a record here. * Fields in record classes are truly final so might help to have a record here.
*/ */
record TimedMethod(AtomicLong invocations, AtomicLong time, Method method, AtomicBoolean published) { record TimedMethod(AtomicLong invocations, AtomicLong time, AtomicLong minimum, AtomicLong maximum, Method method, AtomicBoolean published) {
TimedMethod(Method method) { TimedMethod(Method method) {
this(new AtomicLong(), new AtomicLong(), method, new AtomicBoolean()); this(new AtomicLong(), new AtomicLong(), new AtomicLong(Long.MAX_VALUE), new AtomicLong(Long.MIN_VALUE), method, new AtomicBoolean());
}
public void updateMinMax(long duration) {
if (duration > maximum.getPlain()) {
while (true) {
long max = maximum.get();
if (duration <= max) {
return;
}
if (maximum.weakCompareAndSetVolatile(max, duration)) {
return;
}
}
}
if (duration < minimum.getPlain()) {
while (true) {
long min = minimum.get();
if (duration >= min) {
return;
}
if (minimum.weakCompareAndSetVolatile(min, duration)) {
return;
}
}
}
} }
} }