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

Reviewed-by: mgronlun
This commit is contained in:
Erik Gahlin 2024-06-19 16:23:22 +00:00
parent 01ee4241b7
commit 856931d01f
17 changed files with 154 additions and 70 deletions

View File

@ -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

View File

@ -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

View File

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

View File

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

View File

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

View File

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

View File

@ -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,

View File

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

View File

@ -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 @@ public final class JVM {
*/
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

View File

@ -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 @@ public final class JVMSupport {
lastTimestamp = time;
return;
}
try {
Thread.sleep(0, 100);
} catch (InterruptedException iex) {
// ignore
}
Utils.takeNap(1);
}
}

View File

@ -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 @@ public final class MetadataRepository {
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 @@ public final class MetadataRepository {
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) {

View File

@ -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 abstract class AbstractEventStream implements EventStream {
protected abstract void process() throws IOException;
protected abstract boolean isRecording();
protected abstract boolean isRecordingStream();
protected final void closeParser() {
parserState.close();
@ -249,7 +249,7 @@ public abstract class AbstractEventStream implements EventStream {
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);

View File

@ -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.Arrays;
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 final class EventDirectoryStream extends AbstractEventStream {
}
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 @@ public final class EventDirectoryStream extends AbstractEventStream {
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 @@ public final class EventDirectoryStream extends AbstractEventStream {
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 @@ public final class EventDirectoryStream extends AbstractEventStream {
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 @@ public final class EventDirectoryStream extends AbstractEventStream {
}
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 @@ public final class EventDirectoryStream extends AbstractEventStream {
}
}
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;
}

View File

@ -1,5 +1,5 @@
/*
* Copyright (c) 2019, 2021, 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
@ -73,7 +73,7 @@ public final class EventFileStream extends AbstractEventStream {
}
@Override
protected boolean isRecording() {
protected boolean isRecordingStream() {
return false;
}

View File

@ -1,5 +1,5 @@
/*
* Copyright (c) 2022, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 2022, 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,6 +41,7 @@ import java.io.IOException;
public final class StreamBarrier implements Closeable {
private boolean activated = false;
private boolean used = false;
private long end = Long.MAX_VALUE;
// Blocks thread until barrier is deactivated
@ -62,12 +63,9 @@ public final class StreamBarrier implements Closeable {
return end;
}
public synchronized boolean hasStreamEnd() {
return end != Long.MAX_VALUE;
}
public synchronized void activate() {
activated = true;
used = true;
}
@Override
@ -75,4 +73,11 @@ public final class StreamBarrier implements Closeable {
activated = false;
this.notifyAll();
}
/**
* Returns {@code true) if barrier is, or has been, in active state, {@code false) otherwise.
*/
public synchronized boolean used() {
return used;
}
}

View File

@ -48,6 +48,7 @@ import jdk.internal.module.Checks;
import jdk.jfr.Event;
import jdk.jfr.EventType;
import jdk.jfr.RecordingState;
import jdk.jfr.internal.HiddenWait;
import jdk.jfr.internal.LogLevel;
import jdk.jfr.internal.LogTag;
import jdk.jfr.internal.Logger;
@ -351,8 +352,11 @@ public final class Utils {
}
public static void takeNap(long millis) {
HiddenWait hiddenWait = new HiddenWait();
try {
Thread.sleep(millis);
synchronized(hiddenWait) {
hiddenWait.wait(millis);
}
} catch (InterruptedException e) {
// ok
}

View File

@ -1,5 +1,5 @@
/*
* Copyright (c) 2022, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 2022, 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,7 +41,7 @@ import jdk.jfr.consumer.RecordingStream;
* @requires vm.hasJFR
* @library /test/lib /test/jdk
* @build jdk.jfr.api.consumer.recordingstream.EventProducer
* @run main/othervm jdk.jfr.api.consumer.recordingstream.TestStop
* @run main/othervm -Xlog:system+parser+jfr=info jdk.jfr.api.consumer.recordingstream.TestStop
*/
public class TestStop {
static class StopEvent extends Event {
@ -139,41 +139,50 @@ public class TestStop {
Path fileInner = Path.of("inner.jfr");
inner.dump(fileInner);
outer.dump(fileOuter);
System.out.println("Outer dump:");
var dumpOuter = RecordingFile.readAllEvents(fileOuter);
for (RecordedEvent e : dumpOuter) {
System.out.println(eventToText(e));
}
System.out.println("Inner dump:");
var dumpInner = RecordingFile.readAllEvents(fileInner);
for (RecordedEvent e : dumpInner) {
System.out.println(eventToText(e));
}
System.out.println();
System.out.println("Outer stream:");
for (String s : outerStream) {
System.out.println(s);
}
System.out.println("Inner stream:");
for (String s : innerStream) {
System.out.println(s);
}
if (dumpOuter.size() != 3) {
log(outerStream, innerStream, dumpOuter, dumpInner);
throw new AssertionError("Expected outer dump to have 3 events");
}
if (outerStream.size() != 3) {
log(outerStream, innerStream, dumpOuter, dumpInner);
throw new AssertionError("Expected outer stream to have 3 events");
}
if (dumpInner.size() != 1) {
log(outerStream, innerStream, dumpOuter, dumpInner);
throw new AssertionError("Expected inner dump to have 1 event");
}
if (innerStream.size() != 1) {
log(outerStream, innerStream, dumpOuter, dumpInner);
throw new AssertionError("Expected inner stream to have 1 event");
}
}
}
}
private static void log(List<String> outerStream, List<String> innerStream, List<RecordedEvent> dumpOuter,
List<RecordedEvent> dumpInner) {
System.out.println("Outer dump:");
for (RecordedEvent e : dumpOuter) {
System.out.println(eventToText(e));
}
System.out.println("Inner dump:");
for (RecordedEvent e : dumpInner) {
System.out.println(eventToText(e));
}
System.out.println();
System.out.println("Outer stream:");
for (String s : outerStream) {
System.out.println(s);
}
System.out.println("Inner stream:");
for (String s : innerStream) {
System.out.println(s);
}
}
private static String eventToText(RecordedEvent event) {
Instant timestamp = event.getEndTime();
long s = timestamp.getEpochSecond();