Skip to content

Commit

Permalink
8312474: JFR: Improve logging to diagnose event stream timeout
Browse files Browse the repository at this point in the history
Reviewed-by: mgronlun
  • Loading branch information
egahlin committed Jul 21, 2023
1 parent 3e8f1eb commit 8cd43bf
Show file tree
Hide file tree
Showing 3 changed files with 17 additions and 2 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,9 @@
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;
Expand Down Expand Up @@ -196,6 +199,9 @@ protected void processRecursionSafe() throws IOException {
// 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) {
Expand Down
7 changes: 7 additions & 0 deletions src/jdk.jfr/share/classes/jdk/jfr/internal/dcmd/DCmdView.java
Original file line number Diff line number Diff line change
Expand Up @@ -29,6 +29,9 @@
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;
Expand Down Expand Up @@ -62,6 +65,10 @@ protected void execute(ArgumentParser parser) throws DCmdException {
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);
Expand Down
6 changes: 4 additions & 2 deletions test/jdk/jdk/jfr/jcmd/TestJcmdView.java
Original file line number Diff line number Diff line change
Expand Up @@ -39,7 +39,7 @@
* & 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;
Expand Down Expand Up @@ -94,7 +94,7 @@ public static void main(String... args) throws Throwable {
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
Expand All @@ -105,12 +105,14 @@ public static void main(String... args) throws Throwable {
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();
Expand Down

1 comment on commit 8cd43bf

@openjdk-notifier
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please sign in to comment.