8303135: JFR: Log periodic events using periodic tag

Reviewed-by: mgronlun
This commit is contained in:
Erik Gahlin 2023-02-27 09:47:01 +00:00
parent dbb5581eba
commit fbc036e745
7 changed files with 57 additions and 17 deletions
src
hotspot/share/jfr/utilities
jdk.jfr/share/classes/jdk/jfr/internal

@ -1,5 +1,5 @@
/*
* Copyright (c) 2016, 2021, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 2016, 2023, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
@ -55,6 +55,8 @@
JFR_LOG_TAG(jfr, system, metadata) \
JFR_LOG_TAG(jfr, system, streaming) \
JFR_LOG_TAG(jfr, system, throttle) \
JFR_LOG_TAG(jfr, system, periodic) \
JFR_LOG_TAG(jfr, periodic) \
JFR_LOG_TAG(jfr, metadata) \
JFR_LOG_TAG(jfr, event) \
JFR_LOG_TAG(jfr, setting) \

@ -1,5 +1,5 @@
/*
* Copyright (c) 2016, 2021, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 2016, 2023, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
@ -70,26 +70,34 @@ public enum LogTag {
* Covers throttling (for Hotspot developers)
*/
JFR_SYSTEM_THROTTLE(8),
/**
* Covers periodic task work (for Hotspot developer)
*/
JFR_SYSTEM_PERIODIC(9),
/**
* Covers periodic event work (for users of the JDK)
*/
JFR_PERIODIC(10),
/**
* Covers metadata for Java user (for Hotspot developers)
*/
JFR_METADATA(9),
JFR_METADATA(11),
/**
* Covers events (for users of the JDK)
*/
JFR_EVENT(10),
JFR_EVENT(12),
/**
* Covers setting (for users of the JDK)
*/
JFR_SETTING(11),
JFR_SETTING(13),
/**
* Covers usage of jcmd with JFR
*/
JFR_DCMD(12),
JFR_DCMD(14),
/**
* -XX:StartFlightRecording
*/
JFR_START(13);
JFR_START(15);
/* set from native side */
volatile int tagSetLevel = 100; // prevent logging if JVM log system has not been initialized

@ -50,6 +50,7 @@ final class BatchManager {
}
public void refresh(long iteration, List<PeriodicTask> tasks) {
Logger.log(LogTag.JFR_SYSTEM_PERIODIC, LogLevel.DEBUG, "Grouping tasks into batches. Iteration " + iteration);
groupTasksIntoBatches(tasks);
this.iteration = iteration;
logBatches();
@ -107,19 +108,17 @@ final class BatchManager {
}
private void logBatches() {
if (!Logger.shouldLog(LogTag.JFR, LogLevel.TRACE)) {
if (!Logger.shouldLog(LogTag.JFR_SYSTEM_PERIODIC, LogLevel.TRACE)) {
return;
}
String prefix = "Periodic task: settings iteration: " + iteration + ", batch period: ";
for (Batch batch : batches) {
String batchPrefix = prefix + batch.getPeriod();
for (PeriodicTask task : batch.getTasks()) {
logTrace(batchPrefix + ", period: " + task.getPeriod() + ", task: " + task.getName());
logTrace("Batched task [0.." + task.getPeriod() + "] step " + batch.getPeriod() + " " + task.getName());
}
}
}
private void logTrace(String text) {
Logger.log(LogTag.JFR_SYSTEM, LogLevel.TRACE, text);
Logger.log(LogTag.JFR_SYSTEM_PERIODIC, LogLevel.DEBUG, text);
}
}

@ -33,7 +33,7 @@ abstract class EventTask extends PeriodicTask {
private final PlatformEventType eventType;
public EventTask(PlatformEventType eventType, LookupKey lookupKey) {
super(lookupKey, eventType.getLogName());
super(lookupKey, "event " + eventType.getLogName());
this.eventType = eventType;
}

@ -39,7 +39,7 @@ final class FlushTask extends PeriodicTask {
private volatile long flushInterval = Long.MAX_VALUE;
public FlushTask() {
super(new LookupKey(new Object()), "JFR: Flush Task");
super(new LookupKey(new Object()), "flush task");
}
@Override

@ -31,6 +31,9 @@ import java.util.concurrent.atomic.AtomicLong;
import jdk.jfr.Event;
import jdk.jfr.internal.JVM;
import jdk.jfr.internal.LogLevel;
import jdk.jfr.internal.LogTag;
import jdk.jfr.internal.Logger;
import jdk.jfr.internal.PlatformEventType;
/**
@ -132,6 +135,7 @@ public final class PeriodicEvents {
}
boolean flush = false;
Logger.log(LogTag.JFR_PERIODIC, LogLevel.DEBUG,"Periodic work started");
for (Batch batch : batchManager.getBatches()) {
long left = 0;
long r_period = batch.getPeriod();
@ -178,6 +182,7 @@ public final class PeriodicEvents {
if (flush) {
flushTask.run(eventTimestamp, PeriodicType.INTERVAL);
}
Logger.log(LogTag.JFR_PERIODIC, LogLevel.DEBUG,"Periodic work ended");
lastTimeMillis = now;
return min;
}

@ -89,6 +89,13 @@ abstract class PeriodicTask {
long increment = batch.getPeriod();
if (period != 0) {
counter = (counter + increment) % period;
if (Logger.shouldLog(LogTag.JFR_PERIODIC, LogLevel.DEBUG)) {
boolean trace = Logger.shouldLog(LogTag.JFR_PERIODIC, LogLevel.TRACE);
boolean run = shouldRun();
if (trace || run) {
logInterval(trace, run ? "Run" : "Skip");
}
}
}
}
@ -114,14 +121,33 @@ abstract class PeriodicTask {
}
public final void run(long timestamp, PeriodicType periodicType) {
if (periodicType != PeriodicType.INTERVAL) {
logChunk(periodicType);
}
try {
execute(timestamp, periodicType);
} catch (Throwable e) {
// Prevent malicious user to propagate exception callback in the wrong context
Logger.log(LogTag.JFR_SYSTEM, LogLevel.WARN, "Exception occurred during execution of period task for " + name);
Logger.log(LogTag.JFR_SYSTEM, LogLevel.WARN, "Exception occurred during execution of " + name);
}
if (Logger.shouldLog(LogTag.JFR_SYSTEM, LogLevel.DEBUG)) {
Logger.log(LogTag.JFR_SYSTEM, LogLevel.DEBUG, "Executed periodic task for " + name);
}
private void logChunk(PeriodicType periodicType) {
if (Logger.shouldLog(LogTag.JFR_PERIODIC, LogLevel.DEBUG)) {
String action = periodicType == PeriodicType.BEGIN_CHUNK ? "beginChunk" : "endChunk";
String message = "Run " + action + " " + getName();
Logger.log(LogTag.JFR_PERIODIC, LogLevel.DEBUG, message);
}
}
private void logInterval(boolean trace, String action) {
String message = action + " periodic " + getName();
if (trace) {
// Makes the counter run on x/x instead of 0/x which looks strange.
long a = counter == 0 ? period : counter;
Logger.log(LogTag.JFR_PERIODIC, LogLevel.TRACE, message + (" " + a + "/" + period));
} else {
Logger.log(LogTag.JFR_PERIODIC, LogLevel.DEBUG, message);
}
}
}