8304732: jdk/jfr/api/consumer/recordingstream/TestStop.java failed again with "Expected outer stream to have 3 events"

egahlin · egahlin · commit 856931d01f14 · 2024-06-19T16:23:22.000Z
Reviewed-by: mgronlun
diff --git a/src/hotspot/share/jfr/jni/jfrJniMethod.cpp b/src/hotspot/share/jfr/jni/jfrJniMethod.cpp
@@ -30,6 +30,7 @@
 #include "jfr/recorder/jfrRecorder.hpp"
 #include "jfr/recorder/checkpoint/jfrMetadataEvent.hpp"
 #include "jfr/recorder/checkpoint/types/traceid/jfrTraceId.inline.hpp"
+#include "jfr/recorder/repository/jfrChunk.hpp"
 #include "jfr/recorder/repository/jfrRepository.hpp"
 #include "jfr/recorder/repository/jfrChunkRotation.hpp"
 #include "jfr/recorder/repository/jfrChunkWriter.hpp"
@@ -425,3 +426,7 @@ JVM_END
 JVM_ENTRY_NO_ENV(void, jfr_unregister_stack_filter(JNIEnv* env,  jclass jvm, jlong id))
   JfrStackFilterRegistry::remove(id);
 JVM_END
+
+NO_TRANSITION(jlong, jfr_nanos_now(JNIEnv* env, jclass jvm))
+  return JfrChunk::nanos_now();
+NO_TRANSITION_END
diff --git a/src/hotspot/share/jfr/jni/jfrJniMethod.hpp b/src/hotspot/share/jfr/jni/jfrJniMethod.hpp
@@ -165,6 +165,8 @@ jlong JNICALL jfr_register_stack_filter(JNIEnv* env, jclass jvm, jobjectArray cl
 
 jlong JNICALL jfr_unregister_stack_filter(JNIEnv* env, jclass jvm, jlong id);
 
+jlong JNICALL jfr_nanos_now(JNIEnv* env, jclass jvm);
+
 #ifdef __cplusplus
 }
 #endif
diff --git a/src/hotspot/share/jfr/jni/jfrJniMethodRegistration.cpp b/src/hotspot/share/jfr/jni/jfrJniMethodRegistration.cpp
@@ -100,7 +100,8 @@ JfrJniMethodRegistration::JfrJniMethodRegistration(JNIEnv* env) {
       (char*)"hostTotalSwapMemory", (char*)"()J", (void*) jfr_host_total_swap_memory,
       (char*)"emitDataLoss", (char*)"(J)V", (void*)jfr_emit_data_loss,
       (char*)"registerStackFilter", (char*)"([Ljava/lang/String;[Ljava/lang/String;)J", (void*)jfr_register_stack_filter,
-      (char*)"unregisterStackFilter", (char*)"(J)V", (void*)jfr_unregister_stack_filter
+      (char*)"unregisterStackFilter", (char*)"(J)V", (void*)jfr_unregister_stack_filter,
+      (char*)"nanosNow", (char*)"()J", (void*)jfr_nanos_now
     };
 
     const size_t method_array_length = sizeof(method) / sizeof(JNINativeMethod);
diff --git a/src/hotspot/share/jfr/recorder/repository/jfrChunk.cpp b/src/hotspot/share/jfr/recorder/repository/jfrChunk.cpp
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2012, 2023, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2012, 2024, 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
@@ -35,7 +35,7 @@ static const u2 JFR_VERSION_MAJOR = 2;
 static const u2 JFR_VERSION_MINOR = 1;
 
 // strictly monotone
-static jlong nanos_now() {
+jlong JfrChunk::nanos_now() {
   static jlong last = 0;
 
   jlong seconds;
@@ -147,7 +147,7 @@ void JfrChunk::update_start_ticks() {
 }
 
 void JfrChunk::update_start_nanos() {
-  const jlong now = nanos_now();
+  const jlong now = JfrChunk::nanos_now();
   assert(now >= _start_nanos, "invariant");
   assert(now >= _last_update_nanos, "invariant");
   _start_nanos = _last_update_nanos = now;
diff --git a/src/hotspot/share/jfr/recorder/repository/jfrChunk.hpp b/src/hotspot/share/jfr/recorder/repository/jfrChunk.hpp
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2012, 2019, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2012, 2024, 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
@@ -34,6 +34,8 @@ const u1 PAD = 0;
 class JfrChunk : public JfrCHeapObj {
   friend class JfrChunkWriter;
   friend class JfrChunkHeadWriter;
+ public:
+   static jlong nanos_now();
  private:
   char* _path;
   int64_t _start_ticks;
diff --git a/src/hotspot/share/jfr/support/jfrIntrinsics.hpp b/src/hotspot/share/jfr/support/jfrIntrinsics.hpp
@@ -1,5 +1,5 @@
 /*
-* Copyright (c) 2012, 2023, Oracle and/or its affiliates. All rights reserved.
+* Copyright (c) 2012, 2024, 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
@@ -47,13 +47,13 @@ class JfrIntrinsicSupport : AllStatic {
 #define JFR_HAVE_INTRINSICS
 
 #define JFR_TEMPLATES(template)                                                                                      \
+  template(jdk_jfr_internal_HiddenWait,                               "jdk/jfr/internal/HiddenWait")                 \
   template(jdk_jfr_internal_JVM,                                      "jdk/jfr/internal/JVM")                        \
   template(jdk_jfr_internal_event_EventWriterFactory,                 "jdk/jfr/internal/event/EventWriterFactory")   \
   template(jdk_jfr_internal_event_EventConfiguration_signature,       "Ljdk/jfr/internal/event/EventConfiguration;") \
   template(getEventWriter_signature,                                  "()Ljdk/jfr/internal/event/EventWriter;")      \
   template(eventConfiguration_name,                                   "eventConfiguration")                          \
   template(commit_name,                                               "commit")                                      \
-  template(jfr_chunk_rotation_monitor,                                "jdk/jfr/internal/JVM$ChunkRotationMonitor")   \
 
 #define JFR_INTRINSICS(do_intrinsic, do_class, do_name, do_signature, do_alias)                                      \
   do_intrinsic(_counterTime,        jdk_jfr_internal_JVM, counterTime_name, void_long_signature, F_SN)               \
diff --git a/src/hotspot/share/runtime/objectMonitor.cpp b/src/hotspot/share/runtime/objectMonitor.cpp
@@ -1442,7 +1442,7 @@ bool ObjectMonitor::check_owner(TRAPS) {
 static inline bool is_excluded(const Klass* monitor_klass) {
   assert(monitor_klass != nullptr, "invariant");
   NOT_JFR_RETURN_(false);
-  JFR_ONLY(return vmSymbols::jfr_chunk_rotation_monitor() == monitor_klass->name();)
+  JFR_ONLY(return vmSymbols::jdk_jfr_internal_HiddenWait() == monitor_klass->name();)
 }
 
 static void post_monitor_wait_event(EventJavaMonitorWait* event,
diff --git a/src/jdk.jfr/share/classes/jdk/jfr/internal/HiddenWait.java b/src/jdk.jfr/share/classes/jdk/jfr/internal/HiddenWait.java
@@ -0,0 +1,32 @@
+/*
+ * Copyright (c) 2024, 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
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.  Oracle designates this
+ * particular file as subject to the "Classpath" exception as provided
+ * by Oracle in the LICENSE file that accompanied this code.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ */
+package jdk.jfr.internal;
+
+/**
+ * The HiddenWait class is used to exclude jdk.JavaMonitorWait events
+ * from being generated when Object.wait() is called on an object of this type.
+ */
+public final class HiddenWait {
+}
diff --git a/src/jdk.jfr/share/classes/jdk/jfr/internal/JVM.java b/src/jdk.jfr/share/classes/jdk/jfr/internal/JVM.java
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2017, 2023, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2017, 2024, 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
@@ -41,14 +41,10 @@ public final class JVM {
 
     static final long RESERVED_CLASS_ID_LIMIT = 500;
 
-    private static class ChunkRotationMonitor {}
-
     /*
      * The JVM uses the chunk rotation monitor to notify Java that a rotation is warranted.
-     * The monitor type is used to exclude jdk.JavaMonitorWait events from being generated
-     * when Object.wait() is called on this monitor.
      */
-    public static final Object CHUNK_ROTATION_MONITOR = new ChunkRotationMonitor();
+    public static final Object CHUNK_ROTATION_MONITOR = new HiddenWait();
 
     private static volatile boolean nativeOK;
 
@@ -174,6 +170,11 @@ private static class ChunkRotationMonitor {}
      */
     public static native long getTicksFrequency();
 
+    /**
+     * Returns the same clock that sets the start time of a chunk (in nanos).
+     */
+    public static native long nanosNow();
+
     /**
      * Write message to log. Should swallow null or empty message, and be able
      * to handle any Java character and not crash with very large message
diff --git a/src/jdk.jfr/share/classes/jdk/jfr/internal/JVMSupport.java b/src/jdk.jfr/share/classes/jdk/jfr/internal/JVMSupport.java
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2016, 2023, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2016, 2024, 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
@@ -119,11 +119,7 @@ private static void awaitUniqueTimestamp() {
                 lastTimestamp = time;
                 return;
             }
-            try {
-                Thread.sleep(0, 100);
-            } catch (InterruptedException iex) {
-                // ignore
-            }
+            Utils.takeNap(1);
         }
     }
 
diff --git a/src/jdk.jfr/share/classes/jdk/jfr/internal/MetadataRepository.java b/src/jdk.jfr/share/classes/jdk/jfr/internal/MetadataRepository.java
@@ -64,6 +64,8 @@ public final class MetadataRepository {
     private boolean unregistered;
     private long lastUnloaded = -1;
 
+    private long lastMillis;
+
     public MetadataRepository() {
         initializeJVMEventTypes();
     }
@@ -313,11 +315,12 @@ synchronized Instant setOutput(String filename) {
         if (staleMetadata) {
             storeDescriptorInJVM();
         }
+        // Each chunk needs a unique timestamp. If two chunks get the same
+        // timestamp, the parser may stop prematurely at an earlier chunk.
+        // The resolution needs to be measured in milliseconds as this
+        // is what RecordingInfo:getStopTime() returns.
+        awaitEpochMilliShift();
         JVM.setOutput(filename);
-        // Each chunk needs a unique start timestamp and
-        // if the clock resolution is low, two chunks may
-        // get the same timestamp. Utils.getChunkStartNanos()
-        // ensures the timestamp is unique for the next chunk
         long chunkStart = JVMSupport.getChunkStartNanos();
         if (filename != null) {
             RepositoryFiles.notifyNewFile();
@@ -332,6 +335,18 @@ synchronized Instant setOutput(String filename) {
         return Utils.epochNanosToInstant(chunkStart);
     }
 
+    private void awaitEpochMilliShift() {
+        while (true) {
+            long nanos = JVM.nanosNow();
+            long millis = Utils.epochNanosToInstant(nanos).toEpochMilli();
+            if (millis != lastMillis) {
+                lastMillis = millis;
+                return;
+            }
+            Utils.takeNap(1);
+        }
+    }
+
     private void unregisterUnloaded() {
         long unloaded = JVM.getUnloadedEventClassCount();
         if (this.lastUnloaded != unloaded) {
diff --git a/src/jdk.jfr/share/classes/jdk/jfr/internal/consumer/AbstractEventStream.java b/src/jdk.jfr/share/classes/jdk/jfr/internal/consumer/AbstractEventStream.java
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2019, 2022, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2019, 2024, 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
@@ -205,7 +205,7 @@ public final void awaitTermination(Duration timeout) throws InterruptedException
 
     protected abstract void process() throws IOException;
 
-    protected abstract boolean isRecording();
+    protected abstract boolean isRecordingStream();
 
     protected final void closeParser() {
         parserState.close();
@@ -249,7 +249,7 @@ private void startInternal(long startNanos) {
             if (streamConfiguration.started) {
                 throw new IllegalStateException("Event stream can only be started once");
             }
-            if (isRecording() && streamConfiguration.startTime == null) {
+            if (isRecordingStream() && streamConfiguration.startTime == null) {
                 streamConfiguration.setStartNanos(startNanos);
             }
             streamConfiguration.setStarted(true);
diff --git a/src/jdk.jfr/share/classes/jdk/jfr/internal/consumer/EventDirectoryStream.java b/src/jdk.jfr/share/classes/jdk/jfr/internal/consumer/EventDirectoryStream.java
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2019, 2023, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2019, 2024, 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
@@ -33,9 +33,11 @@
 import java.util.Comparator;
 import java.util.List;
 import java.util.Objects;
+import java.util.concurrent.atomic.AtomicLong;
 import java.util.function.Consumer;
 
 import jdk.jfr.Configuration;
+import jdk.jfr.RecordingState;
 import jdk.jfr.consumer.RecordedEvent;
 import jdk.jfr.internal.JVM;
 import jdk.jfr.internal.LogLevel;
@@ -59,6 +61,7 @@ public final class EventDirectoryStream extends AbstractEventStream {
     private final FileAccess fileAccess;
     private final PlatformRecording recording;
     private final StreamBarrier barrier = new StreamBarrier();
+    private final AtomicLong streamId = new AtomicLong();
     private ChunkParser currentParser;
     private long currentChunkStartNanos;
     private RecordedEvent[] sortedCache;
@@ -80,6 +83,8 @@ public EventDirectoryStream(
         }
         this.fileAccess = Objects.requireNonNull(fileAccess);
         this.repositoryFiles = new RepositoryFiles(fileAccess, p, allowSubDirectories);
+        this.streamId.incrementAndGet();
+        Logger.log(LogTag.JFR_SYSTEM_PARSER, LogLevel.INFO, "Stream " + streamId + " started.");
     }
 
     @Override
@@ -137,13 +142,14 @@ protected void processRecursionSafe() throws IOException {
         Dispatcher lastDisp = null;
         Dispatcher disp = dispatcher();
         Path path;
-        boolean validStartTime = isRecording() || disp.startTime != null;
+        boolean validStartTime = isRecordingStream() || disp.startTime != null;
         if (validStartTime) {
             path = repositoryFiles.firstPath(disp.startNanos, true);
         } else {
             path = repositoryFiles.lastPath(true);
         }
         if (path == null) { // closed
+            logStreamEnd("no first chunk file found.");
             return;
         }
         currentChunkStartNanos = repositoryFiles.getTimestamp(path);
@@ -168,7 +174,10 @@ protected void processRecursionSafe() throws IOException {
                         processUnordered(disp);
                     }
                     currentParser.resetCache();
-                    if (currentParser.getLastFlush() > filterEnd) {
+                    long lastFlush = currentParser.getLastFlush();
+                    if (lastFlush  > filterEnd) {
+                        logStreamEnd("end time at " + filterEnd +
+                                     "ns (epoch), parser at " + lastFlush + "ns (epoch).");
                         return;
                     }
                 }
@@ -177,20 +186,25 @@ protected void processRecursionSafe() throws IOException {
 
                 barrier.check(); // block if recording is being stopped
                 if (barrier.getStreamEnd() <= endMillis) {
+                    String msg = "stopped at " + barrier.getStreamEnd() + "ms (epoch), ";
+                    msg += "parser at " + endMillis + "ms (epoch), " + endNanos + "ns (epoch)";
+                    logStreamEnd(msg);
                     return;
                 }
 
-                if (!barrier.hasStreamEnd() && isLastChunk()) {
-                    // Recording was stopped/closed externally, and no more data to process.
-                    return;
+                if (isRecordingStream()) {
+                    if (recording.getState() == RecordingState.STOPPED && !barrier.used()) {
+                        logStreamEnd("recording stopped externally.");
+                        return;
+                    }
                 }
 
                 if (repositoryFiles.hasFixedPath() && currentParser.isFinalChunk()) {
-                    // JVM process exited/crashed, or repository migrated to an unknown location
+                    logStreamEnd("JVM process exited/crashed, or repository migrated to an unknown location.");
                     return;
                 }
                 if (isClosed()) {
-                    // Stream was closed
+                    logStreamEnd("stream closed.");
                     return;
                 }
                 long durationNanos = currentParser.getChunkDuration();
@@ -205,7 +219,8 @@ protected void processRecursionSafe() throws IOException {
                 }
                 path = repositoryFiles.nextPath(currentChunkStartNanos + durationNanos, true);
                 if (path == null) {
-                    return; // stream closed
+                    logStreamEnd("no more chunk files found.");
+                    return;
                 }
                 currentChunkStartNanos = repositoryFiles.getTimestamp(path);
                 input.setFile(path);
@@ -217,15 +232,12 @@ protected void processRecursionSafe() throws IOException {
         }
     }
 
-
-    private boolean isLastChunk() {
-        if (!isRecording()) {
-            return false;
-        }
-        return recording.getFinalChunkStartNanos() >= currentParser.getStartNanos();
+    private void logStreamEnd(String text) {
+        String msg = "Stream " + streamId + " ended, " + text;
+        Logger.log(LogTag.JFR_SYSTEM_PARSER, LogLevel.INFO, msg);
     }
 
-    protected boolean isRecording() {
+    protected boolean isRecordingStream() {
         return recording != null;
     }
 
diff --git a/src/jdk.jfr/share/classes/jdk/jfr/internal/consumer/EventFileStream.java b/src/jdk.jfr/share/classes/jdk/jfr/internal/consumer/EventFileStream.java
diff --git a/src/jdk.jfr/share/classes/jdk/jfr/internal/management/StreamBarrier.java b/src/jdk.jfr/share/classes/jdk/jfr/internal/management/StreamBarrier.java
diff --git a/src/jdk.jfr/share/classes/jdk/jfr/internal/util/Utils.java b/src/jdk.jfr/share/classes/jdk/jfr/internal/util/Utils.java
diff --git a/test/jdk/jdk/jfr/api/consumer/recordingstream/TestStop.java b/test/jdk/jdk/jfr/api/consumer/recordingstream/TestStop.java

Original file line number	Diff line number	Diff line change
`@@ -165,6 +165,8 @@ jlong JNICALL jfr_register_stack_filter(JNIEnv* env, jclass jvm, jobjectArray cl`
`165`	`165`
`166`	`166`	`jlong JNICALL jfr_unregister_stack_filter(JNIEnv* env, jclass jvm, jlong id);`
`167`	`167`
	`168`	`+jlong JNICALL jfr_nanos_now(JNIEnv* env, jclass jvm);`
	`169`	`+`
`168`	`170`	`#ifdef __cplusplus`
`169`	`171`	`}`
`170`	`172`	`#endif`
Original file line number	Diff line number	Diff line change
`@@ -1442,7 +1442,7 @@ bool ObjectMonitor::check_owner(TRAPS) {`
`1442`	`1442`	`static inline bool is_excluded(const Klass* monitor_klass) {`
`1443`	`1443`	`assert(monitor_klass != nullptr, "invariant");`
`1444`	`1444`	`NOT_JFR_RETURN_(false);`
`1445`		`- JFR_ONLY(return vmSymbols::jfr_chunk_rotation_monitor() == monitor_klass->name();)`
	`1445`	`+ JFR_ONLY(return vmSymbols::jdk_jfr_internal_HiddenWait() == monitor_klass->name();)`
`1446`	`1446`	`}`
`1447`	`1447`
`1448`	`1448`	`static void post_monitor_wait_event(EventJavaMonitorWait* event,`
Original file line number	Diff line number	Diff line change
`@@ -1,5 +1,5 @@`
`1`	`1`	`/*`
`2`		`- * Copyright (c) 2016, 2023, Oracle and/or its affiliates. All rights reserved.`
	`2`	`+ * Copyright (c) 2016, 2024, Oracle and/or its affiliates. All rights reserved.`
`3`	`3`	`* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.`
`4`	`4`	`*`
`5`	`5`	`* This code is free software; you can redistribute it and/or modify it`
`@@ -119,11 +119,7 @@ private static void awaitUniqueTimestamp() {`
`119`	`119`	`lastTimestamp = time;`
`120`	`120`	`return;`
`121`	`121`	`}`
`122`		`- try {`
`123`		`- Thread.sleep(0, 100);`
`124`		`- } catch (InterruptedException iex) {`
`125`		`- // ignore`
`126`		`- }`
	`122`	`+ Utils.takeNap(1);`
`127`	`123`	`}`
`128`	`124`	`}`
`129`	`125`