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

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

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

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);

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;

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;

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)               \

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,

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 {
+}

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

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);
         }
     }
 

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) {

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);

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;
     }