8312474: JFR: Improve logging to diagnose event stream timeout

Reviewed-by: mgronlun
This commit is contained in:
Erik Gahlin 2023-07-21 08:09:52 +00:00
parent 3e8f1eb820
commit 8cd43bff3c
3 changed files with 17 additions and 2 deletions
src/jdk.jfr/share/classes/jdk/jfr/internal
test/jdk/jdk/jfr/jcmd

@ -38,6 +38,9 @@ import java.util.function.Consumer;
import jdk.jfr.Configuration;
import jdk.jfr.consumer.RecordedEvent;
import jdk.jfr.internal.JVM;
import jdk.jfr.internal.LogLevel;
import jdk.jfr.internal.LogTag;
import jdk.jfr.internal.Logger;
import jdk.jfr.internal.PlatformRecording;
import jdk.jfr.internal.SecuritySupport;
import jdk.jfr.internal.util.Utils;
@ -196,6 +199,9 @@ public final class EventDirectoryStream extends AbstractEventStream {
// Avoid reading the same chunk again and again if
// duration is 0 ns
durationNanos++;
if (Logger.shouldLog(LogTag.JFR_SYSTEM_PARSER, LogLevel.INFO)) {
Logger.log(LogTag.JFR_SYSTEM_PARSER, LogLevel.INFO, "Unexpected chunk with 0 ns duration");
}
}
path = repositoryFiles.nextPath(currentChunkStartNanos + durationNanos, true);
if (path == null) {

@ -29,6 +29,9 @@ import java.time.Instant;
import java.util.ArrayList;
import java.util.List;
import jdk.jfr.internal.LogLevel;
import jdk.jfr.internal.LogTag;
import jdk.jfr.internal.Logger;
import jdk.jfr.internal.OldObjectSample;
import jdk.jfr.internal.util.Utils;
import jdk.jfr.internal.query.Configuration;
@ -62,6 +65,10 @@ public class DCmdView extends AbstractDCmd {
Utils.waitFlush(10_000);
configuration.endTime = Instant.now();
}
if (Logger.shouldLog(LogTag.JFR_DCMD, LogLevel.DEBUG)) {
Logger.log(LogTag.JFR_DCMD, LogLevel.DEBUG, "JFR.view time range: " + configuration.startTime + " - " + configuration.endTime);
}
try (QueryRecording recording = new QueryRecording(configuration, parser)) {
ViewPrinter printer = new ViewPrinter(configuration, recording.getStream());
printer.execute(view);

@ -39,7 +39,7 @@ import jdk.test.lib.process.OutputAnalyzer;
* & vm.opt.ExplicitGCInvokesConcurrent != false
* @library /test/lib /test/jdk
* @run main/othervm -XX:-ExplicitGCInvokesConcurrent -XX:-DisableExplicitGC
* -XX:+UseG1GC jdk.jfr.jcmd.TestJcmdView
* -XX:+UseG1GC -Xlog:jfr+dcmd=debug -Xlog:jfr+system+parser=info jdk.jfr.jcmd.TestJcmdView
*/
public class TestJcmdView {
private static volatile Instant lastTimestamp;
@ -94,7 +94,7 @@ public class TestJcmdView {
jvmInformation.await();
systemGC.await();
gcHeapSummary.await();
oldCollection.countDown();
oldCollection.await();
// Wait for Instant.now() to advance 1 s past the last event timestamp.
// The rationale for this is twofold:
// - DcmdView starts one second before Instant.now() (to make the command
@ -105,12 +105,14 @@ public class TestJcmdView {
while (Instant.now().isBefore(end)) {
Thread.sleep(10);
}
System.out.println("Time before testEventType() " + Instant.now());
// Test events that are in the current chunk
testEventType();
testFormView();
testTableView();
rs.disable("jdk.JVMInformation");
// Force chunk rotation
System.out.println("About to rotate chunk");
rotate();
// Test events that are NOT in current chunk
testEventType();