changeset 52981:4eff16f47ae2

8165675: Trace event for thread park has incorrect unit for timeout Reviewed-by: mgronlun
author egahlin
date Wed, 12 Dec 2018 18:35:26 +0100
parents 24525070d934
children 122b1ecfaa6e
files src/hotspot/share/jfr/metadata/metadata.xml src/hotspot/share/prims/unsafe.cpp src/java.base/share/classes/jdk/internal/event/EventHelper.java src/jdk.jfr/share/classes/jdk/jfr/consumer/RecordedObject.java src/jdk.jfr/share/classes/jdk/jfr/internal/tool/PrettyWriter.java test/jdk/jdk/jfr/event/runtime/TestThreadParkEvent.java test/jdk/jdk/jfr/jmx/security/TestEnoughPermission.java test/lib/jdk/test/lib/jfr/Events.java
diffstat 8 files changed, 158 insertions(+), 20 deletions(-) [+]
line wrap: on
line diff
--- a/src/hotspot/share/jfr/metadata/metadata.xml	Wed Dec 12 14:18:16 2018 +0100
+++ b/src/hotspot/share/jfr/metadata/metadata.xml	Wed Dec 12 18:35:26 2018 +0100
@@ -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>
--- a/src/hotspot/share/prims/unsafe.cpp	Wed Dec 12 14:18:16 2018 +0100
+++ b/src/hotspot/share/prims/unsafe.cpp	Wed Dec 12 18:35:26 2018 +0100
@@ -926,11 +926,12 @@
   }
 } 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 @@
   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
--- a/src/java.base/share/classes/jdk/internal/event/EventHelper.java	Wed Dec 12 14:18:16 2018 +0100
+++ b/src/java.base/share/classes/jdk/internal/event/EventHelper.java	Wed Dec 12 18:35:26 2018 +0100
@@ -101,6 +101,9 @@
      */
     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) {
--- a/src/jdk.jfr/share/classes/jdk/jfr/consumer/RecordedObject.java	Wed Dec 12 14:18:16 2018 +0100
+++ b/src/jdk.jfr/share/classes/jdk/jfr/consumer/RecordedObject.java	Wed Dec 12 18:35:26 2018 +0100
@@ -726,6 +726,9 @@
 
     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 @@
                 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 @@
 
     // 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());
     }
 
--- a/src/jdk.jfr/share/classes/jdk/jfr/internal/tool/PrettyWriter.java	Wed Dec 12 14:18:16 2018 +0100
+++ b/src/jdk.jfr/share/classes/jdk/jfr/internal/tool/PrettyWriter.java	Wed Dec 12 18:35:26 2018 +0100
@@ -281,7 +281,7 @@
 
     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 @@
                 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 @@
     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 @@
             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);
--- a/test/jdk/jdk/jfr/event/runtime/TestThreadParkEvent.java	Wed Dec 12 14:18:16 2018 +0100
+++ b/test/jdk/jdk/jfr/event/runtime/TestThreadParkEvent.java	Wed Dec 12 18:35:26 2018 +0100
@@ -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 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 @@
         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 @@
             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;
     }
 
 }
--- a/test/jdk/jdk/jfr/jmx/security/TestEnoughPermission.java	Wed Dec 12 14:18:16 2018 +0100
+++ b/test/jdk/jdk/jfr/jmx/security/TestEnoughPermission.java	Wed Dec 12 18:35:26 2018 +0100
@@ -85,7 +85,7 @@
         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;
--- a/test/lib/jdk/test/lib/jfr/Events.java	Wed Dec 12 14:18:16 2018 +0100
+++ b/test/lib/jdk/test/lib/jfr/Events.java	Wed Dec 12 18:35:26 2018 +0100
@@ -33,12 +33,16 @@
 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 @@
         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");