8165675: Trace event for thread park has incorrect unit for timeout

Reviewed-by: mgronlun
This commit is contained in:
Erik Gahlin 2018-12-12 18:35:26 +01:00
parent b7bd4bccbf
commit 85ffc2803c
8 changed files with 158 additions and 20 deletions
src
hotspot/share
jfr/metadata
prims
java.base/share/classes/jdk/internal/event
jdk.jfr/share/classes/jdk/jfr
test
jdk/jdk/jfr
lib/jdk/test/lib/jfr

@ -40,7 +40,8 @@
<Event name="ThreadPark" category="Java Application" label="Java Thread Park" thread="true" stackTrace="true">
<Field type="Class" name="parkedClass" label="Class Parked On" />
<Field type="long" contentType="millis" name="timeout" label="Park Timeout" />
<Field type="long" contentType="nanos" name="timeout" label="Park Timeout" />
<Field type="long" contentType="epochmillis" name="until" label="Park Until" />
<Field type="ulong" contentType="address" name="address" label="Address of Object Parked" relation="JavaMonitorAddress" />
</Event>
@ -1140,5 +1141,6 @@
<XmlContentType name="address" annotationType="jdk.jfr.MemoryAddress" />
<XmlContentType name="percentage" annotationType="jdk.jfr.Percentage" />
<XmlContentType name="millis" annotationType="jdk.jfr.Timespan" annotationValue="MILLISECONDS" />
<XmlContentType name="nanos" annotationType="jdk.jfr.Timespan" annotationValue="NANOSECONDS" />
</Metadata>

@ -926,11 +926,12 @@ UNSAFE_ENTRY(jboolean, Unsafe_CompareAndSetLong(JNIEnv *env, jobject unsafe, job
}
} UNSAFE_END
static void post_thread_park_event(EventThreadPark* event, const oop obj, jlong timeout) {
static void post_thread_park_event(EventThreadPark* event, const oop obj, jlong timeout_nanos, jlong until_epoch_millis) {
assert(event != NULL, "invariant");
assert(event->should_commit(), "invariant");
event->set_parkedClass((obj != NULL) ? obj->klass() : NULL);
event->set_timeout(timeout);
event->set_timeout(timeout_nanos);
event->set_until(until_epoch_millis);
event->set_address((obj != NULL) ? (u8)cast_from_oop<uintptr_t>(obj) : 0);
event->commit();
}
@ -942,7 +943,16 @@ UNSAFE_ENTRY(void, Unsafe_Park(JNIEnv *env, jobject unsafe, jboolean isAbsolute,
JavaThreadParkedState jtps(thread, time != 0);
thread->parker()->park(isAbsolute != 0, time);
if (event.should_commit()) {
post_thread_park_event(&event, thread->current_park_blocker(), time);
const oop obj = thread->current_park_blocker();
if (time == 0) {
post_thread_park_event(&event, obj, min_jlong, min_jlong);
} else {
if (isAbsolute != 0) {
post_thread_park_event(&event, obj, min_jlong, time);
} else {
post_thread_park_event(&event, obj, time, min_jlong);
}
}
}
HOTSPOT_THREAD_PARK_END((uintptr_t) thread->parker());
} UNSAFE_END

@ -101,6 +101,9 @@ public final class EventHelper {
*/
private static String getDurationString(Instant start) {
if (start != null) {
if (start.equals(Instant.MIN)) {
return "N/A";
}
Duration duration = Duration.between(start, Instant.now());
long micros = duration.toNanos() / 1_000;
if (micros < 1_000_000) {

@ -726,6 +726,9 @@ public class RecordedObject {
private Duration getDuration(long timespan, String name) throws InternalError {
ValueDescriptor v = getValueDescriptor(descriptors, name, null);
if (timespan == Long.MIN_VALUE) {
return Duration.ofSeconds(Long.MIN_VALUE, 0);
}
Timespan ts = v.getAnnotation(Timespan.class);
if (ts != null) {
switch (ts.value()) {
@ -797,13 +800,16 @@ public class RecordedObject {
return getInstant(Short.toUnsignedLong((Byte) u), name);
}
}
throw newIllegalArgumentException(name, "java,time.Instant");
throw newIllegalArgumentException(name, "java.time.Instant");
}
private Instant getInstant(long timestamp, String name) {
ValueDescriptor v = getValueDescriptor(descriptors, name, null);
Timestamp ts = v.getAnnotation(Timestamp.class);
if (ts != null) {
if (timestamp == Long.MIN_VALUE) {
return Instant.MIN;
}
switch (ts.value()) {
case Timestamp.MILLISECONDS_SINCE_EPOCH:
return Instant.ofEpochMilli(timestamp);
@ -884,6 +890,10 @@ public class RecordedObject {
// package private for now. Used by EventWriter
OffsetDateTime getOffsetDateTime(String name) {
Instant instant = getInstant(name);
if (instant.equals(Instant.MIN)) {
return OffsetDateTime.MIN;
}
return OffsetDateTime.ofInstant(getInstant(name), timeConverter.getZoneOffset());
}

@ -281,7 +281,7 @@ public final class PrettyWriter extends EventPrintWriter {
private void printValue(Object value, ValueDescriptor field, String postFix) {
if (value == null) {
println("null" + postFix);
println("N/A" + postFix);
return;
}
if (value instanceof RecordedObject) {
@ -320,6 +320,35 @@ public final class PrettyWriter extends EventPrintWriter {
return;
}
}
if (value instanceof Double) {
Double d = (Double) value;
if (Double.isNaN(d) || d == Double.NEGATIVE_INFINITY) {
println("N/A");
return;
}
}
if (value instanceof Float) {
Float f = (Float) value;
if (Float.isNaN(f) || f == Float.NEGATIVE_INFINITY) {
println("N/A");
return;
}
}
if (value instanceof Long) {
Long l = (Long) value;
if (l == Long.MIN_VALUE) {
println("N/A");
return;
}
}
if (value instanceof Integer) {
Integer i = (Integer) value;
if (i == Integer.MIN_VALUE) {
println("N/A");
return;
}
}
String text = String.valueOf(value);
if (value instanceof String) {
text = "\"" + text + "\"";
@ -443,6 +472,10 @@ public final class PrettyWriter extends EventPrintWriter {
private boolean printFormatted(ValueDescriptor field, Object value) {
if (value instanceof Duration) {
Duration d = (Duration) value;
if (d.getSeconds() == Long.MIN_VALUE) {
println("N/A");
return true;
}
double s = d.toNanosPart() / 1000_000_000.0 + d.toSecondsPart();
if (s < 1.0) {
if (s < 0.001) {
@ -460,8 +493,12 @@ public final class PrettyWriter extends EventPrintWriter {
return true;
}
if (value instanceof OffsetDateTime) {
OffsetDateTime zdt = (OffsetDateTime) value;
println(TIME_FORMAT.format(zdt));
OffsetDateTime odt = (OffsetDateTime) value;
if (odt.equals(OffsetDateTime.MIN)) {
println("N/A");
return true;
}
println(TIME_FORMAT.format(odt));
return true;
}
Percentage percentage = field.getAnnotation(Percentage.class);

@ -25,22 +25,25 @@
package jdk.jfr.event.runtime;
import static jdk.test.lib.Asserts.assertFalse;
import static jdk.test.lib.Asserts.assertTrue;
import java.nio.file.Files;
import java.nio.file.Paths;
import java.time.Duration;
import java.time.Instant;
import java.util.List;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.locks.LockSupport;
import java.util.function.Consumer;
import jdk.jfr.Recording;
import jdk.jfr.consumer.RecordedEvent;
import jdk.test.lib.Asserts;
import jdk.test.lib.jfr.EventNames;
import jdk.test.lib.jfr.Events;
import jdk.test.lib.management.ThreadMXBeanTool;
import jdk.test.lib.thread.TestThread;
/**
* @test
* @key jfr
@ -58,12 +61,39 @@ public class TestThreadParkEvent {
}
public static void main(String[] args) throws Throwable {
testParkNoTimeout();
testParkTimeout();
testParkUntil();
}
private static void testParkNoTimeout() throws Exception {
RecordedEvent event = testPark(x -> LockSupport.park(x), Thread.State.WAITING);
Events.assertMissingValue(event, "timeout");
Events.assertMissingValue(event, "until");
}
private static void testParkTimeout() throws Exception {
Duration expected = Duration.ofNanos(1_234_567_890_123L);
RecordedEvent event = testPark(x -> LockSupport.parkNanos(x, expected.toNanos()), Thread.State.TIMED_WAITING);
Events.assertDuration(event, "timeout", expected);
Events.assertMissingValue(event, "until");
}
private static void testParkUntil() throws Exception {
long epochMillis = Instant.now().plusSeconds(1000000).toEpochMilli();
RecordedEvent event = testPark(x -> LockSupport.parkUntil(x, epochMillis), Thread.State.TIMED_WAITING);
Events.assertMissingValue(event, "timeout");
Events.assertInstant(event, "until", Instant.ofEpochMilli(epochMillis));
}
static RecordedEvent testPark(Consumer<Blocker> parkOperation, Thread.State threadState) throws Exception {
final CountDownLatch stop = new CountDownLatch(1);
final Blocker blocker = new Blocker();
TestThread parkThread = new TestThread(new Runnable() {
public void run() {
while (stop.getCount() > 0) {
LockSupport.park(blocker);
parkOperation.accept(blocker);
}
}
});
@ -73,7 +103,7 @@ public class TestThreadParkEvent {
try {
recording.start();
parkThread.start();
ThreadMXBeanTool.waitUntilBlockingOnObject(parkThread, Thread.State.WAITING, blocker);
ThreadMXBeanTool.waitUntilBlockingOnObject(parkThread, threadState, blocker);
// sleep so we know the event is recorded
Thread.sleep(2 * THRESHOLD_MILLIS);
} finally {
@ -82,22 +112,21 @@ public class TestThreadParkEvent {
parkThread.join();
recording.stop();
}
List<RecordedEvent> events = Events.fromRecording(recording);
Events.hasEvents(events);
boolean isAnyFound = false;
RecordedEvent foundEvent = null;
for (RecordedEvent event : events) {
System.out.println("Event:" + event);
String klassName = Events.assertField(event, "parkedClass.name").notNull().getValue();
if (klassName.equals(blocker.getClass().getName().replace('.', '/'))) {
assertFalse(isAnyFound, "Found more than 1 event");
isAnyFound = true;
Events.assertField(event, "timeout").equal(0L);
Asserts.assertNull(foundEvent , "Found more than 1 event");
Events.assertField(event, "address").notEqual(0L);
Events.assertEventThread(event, parkThread);
foundEvent = event;
}
}
assertTrue(isAnyFound, "Correct event not found");
Asserts.assertNotNull(foundEvent, "Correct event not found");
return foundEvent;
}
}

@ -85,7 +85,7 @@ public class TestEnoughPermission {
System.out.println("E");
bean.stopRecording(recId);
final Path path = Paths.get(".", String.format("rec%d.jfr", recId));
final Path path = Paths.get(".", "rec" + recId + ".jfr");
bean.copyTo(recId, path.toString());
//EventSet events = EventSet.fromFile(path);
return recId;

@ -33,12 +33,16 @@ import static jdk.test.lib.Asserts.fail;
import java.io.File;
import java.io.IOException;
import java.nio.file.Path;
import java.time.Duration;
import java.time.Instant;
import java.util.List;
import jdk.jfr.AnnotationElement;
import jdk.jfr.EventType;
import jdk.jfr.Recording;
import jdk.jfr.SettingDescriptor;
import jdk.jfr.Timespan;
import jdk.jfr.Timestamp;
import jdk.jfr.ValueDescriptor;
import jdk.jfr.consumer.RecordingFile;
import jdk.test.lib.Asserts;
@ -183,6 +187,49 @@ public class Events {
assertThread(assertField(event, structName).notNull().getValue(), thread);
}
public static void assertDuration(RecordedEvent event, String name, Duration duration) {
assertEquals(event.getDuration(name), duration);
}
public static void assertInstant(RecordedEvent event, String name, Instant instant) {
assertEquals(event.getInstant(name), instant);
}
public static void assertMissingValue(RecordedEvent event, String name) {
ValueDescriptor v = event.getEventType().getField(name);
if (v.getAnnotation(Timespan.class) != null) {
Duration d = event.getDuration(name);
assertTrue(d.getSeconds() == Long.MIN_VALUE && d.getNano() == 0);
return;
}
if (v.getAnnotation(Timestamp.class) != null) {
Instant instant = event.getInstant(name);
assertTrue(instant.equals(Instant.MIN));
return;
}
if (v.getTypeName().equals("double")) {
double d = event.getDouble(name);
assertTrue(Double.isNaN(d) || d == Double.NEGATIVE_INFINITY);
return;
}
if (v.getTypeName().equals("float")) {
float f = event.getFloat(name);
assertTrue(Float.isNaN(f) || f == Float.NEGATIVE_INFINITY);
return;
}
if (v.getTypeName().equals("int")) {
int i = event.getInt(name);
assertTrue(i == Integer.MIN_VALUE);
return;
}
if (v.getTypeName().equals("long")) {
assertEquals(event.getLong(name), Long.MIN_VALUE);
return;
}
Object o = event.getValue(name);
Asserts.assertNull(o);
}
private static void assertThread(RecordedThread eventThread, Thread thread) {
assertNotNull(eventThread, "Thread in event was null");
assertEquals(eventThread.getJavaThreadId(), thread.getId(), "Wrong thread id");