Take timestamp on commit JEP-349-branch
authoregahlin
Thu, 22 Aug 2019 20:36:52 +0200
branchJEP-349-branch
changeset 57848 bd961c64ecce
parent 57784 88316b070ab9
child 57857 d957ea28ed21
Take timestamp on commit
src/jdk.jfr/share/classes/jdk/jfr/internal/EventInstrumentation.java
test/jdk/jdk/jfr/api/consumer/recordingstream/TestSetEndTime.java
--- a/src/jdk.jfr/share/classes/jdk/jfr/internal/EventInstrumentation.java	Fri Aug 16 20:50:32 2019 +0200
+++ b/src/jdk.jfr/share/classes/jdk/jfr/internal/EventInstrumentation.java	Thu Aug 22 20:36:52 2019 +0200
@@ -121,7 +121,7 @@
     private final boolean untypedEventHandler;
     private boolean guardHandlerReference;
     private Class<?> superClass;
-    private final static boolean streamingCommit = !SecuritySupport.getBooleanProperty("jfr.instrument.streaming");
+    private final static boolean streamingCommit = true; //!SecuritySupport.getBooleanProperty("jfr.instrument.streaming");
 
     EventInstrumentation(Class<?> superClass, byte[] bytes, long id) {
         this.superClass = superClass;
@@ -367,36 +367,90 @@
         // MyEvent#commit() - Java event writer
         if (streamingCommit) {
             updateMethod(METHOD_COMMIT, methodVisitor -> {
-                // if (shouldCommit()) {
+                methodVisitor.visitCode();
+                // Labels
+                Label enabled = new Label();
+                Label end = new Label();
+                Label durationEvent = new Label();
+                Label writeToHandler = new Label();
+                Label timestampOnCommit = new Label();
+                // if (!isEnable()) {
+                // return;
+                // }
                 methodVisitor.visitCode();
                 methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
-                methodVisitor.visitMethodInsn(Opcodes.INVOKEVIRTUAL, getInternalClassName(), METHOD_EVENT_SHOULD_COMMIT.getName(), METHOD_EVENT_SHOULD_COMMIT.getDescriptor(), false);
-                Label end = new Label();
-                methodVisitor.visitJumpInsn(Opcodes.IFEQ, end);
+                methodVisitor.visitMethodInsn(Opcodes.INVOKEVIRTUAL, getInternalClassName(), METHOD_IS_ENABLED.getName(), METHOD_IS_ENABLED.getDescriptor(), false);
+                methodVisitor.visitJumpInsn(Opcodes.IFNE, enabled);
+                methodVisitor.visitInsn(Opcodes.RETURN);
+                methodVisitor.visitLabel(enabled);
+                methodVisitor.visitFrame(Opcodes.F_SAME, 0, null, 0, null);
+
+                // if (startTime == 0) {
+                // startTime = EventWriter.timestamp();
+                // } else {
+                methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
+                methodVisitor.visitFieldInsn(Opcodes.GETFIELD, getInternalClassName(), FIELD_START_TIME, "J");
+                methodVisitor.visitInsn(Opcodes.LCONST_0);
+                methodVisitor.visitInsn(Opcodes.LCMP);
+                methodVisitor.visitJumpInsn(Opcodes.IFNE, durationEvent);
+                methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
+                methodVisitor.visitMethodInsn(Opcodes.INVOKESTATIC, TYPE_EVENT_HANDLER.getInternalName(), METHOD_TIME_STAMP.getName(), METHOD_TIME_STAMP.getDescriptor(), false);
+                methodVisitor.visitFieldInsn(Opcodes.PUTFIELD, getInternalClassName(), FIELD_START_TIME, "J");
+                methodVisitor.visitJumpInsn(Opcodes.GOTO, writeToHandler);
+
+                // new
+                // if (duration == 0) {
+                methodVisitor.visitLabel(durationEvent);
                 methodVisitor.visitFrame(Opcodes.F_SAME, 0, null, 0, null);
                 methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
-                //   startTime = EventHandler.timestamp() - duration;
-                methodVisitor.visitMethodInsn(Opcodes.INVOKESTATIC, TYPE_EVENT_HANDLER.getInternalName(), METHOD_TIME_STAMP.getName(),
-                        METHOD_TIME_STAMP.getDescriptor(), false);
+                methodVisitor.visitFieldInsn(Opcodes.GETFIELD, getInternalClassName(), FIELD_DURATION, "J");
+                methodVisitor.visitInsn(Opcodes.LCONST_0);
+                methodVisitor.visitInsn(Opcodes.LCMP);
+                methodVisitor.visitJumpInsn(Opcodes.IFNE, timestampOnCommit);
+
+                // startTime = EventWriter.timestamp() - duration;
+                methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
+                methodVisitor.visitMethodInsn(Opcodes.INVOKESTATIC, TYPE_EVENT_HANDLER.getInternalName(), METHOD_TIME_STAMP.getName(), METHOD_TIME_STAMP.getDescriptor(), false);
                 methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
                 methodVisitor.visitFieldInsn(Opcodes.GETFIELD, getInternalClassName(), FIELD_DURATION, "J");
                 methodVisitor.visitInsn(Opcodes.LSUB);
                 methodVisitor.visitFieldInsn(Opcodes.PUTFIELD, getInternalClassName(), FIELD_START_TIME, "J");
+                methodVisitor.visitJumpInsn(Opcodes.GOTO, writeToHandler);
+
+                // duration = EventWriter.timestamp() -timestamp
+                // }
+                methodVisitor.visitLabel(timestampOnCommit);
+                methodVisitor.visitFrame(Opcodes.F_SAME, 0, null, 0, null);
+                methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
+                methodVisitor.visitMethodInsn(Opcodes.INVOKESTATIC, TYPE_EVENT_HANDLER.getInternalName(), METHOD_TIME_STAMP.getName(), METHOD_TIME_STAMP.getDescriptor(), false);
+                methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
+                methodVisitor.visitFieldInsn(Opcodes.GETFIELD, getInternalClassName(), FIELD_START_TIME, "J");
+                methodVisitor.visitInsn(Opcodes.LSUB);
+                methodVisitor.visitFieldInsn(Opcodes.PUTFIELD, getInternalClassName(), FIELD_DURATION, "J");
+
+                // if (shouldCommit()) {
+                 methodVisitor.visitLabel(writeToHandler);
+                 methodVisitor.visitFrame(Opcodes.F_SAME, 0, null, 0, null);
+                 methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
+                 methodVisitor.visitMethodInsn(Opcodes.INVOKESPECIAL, getInternalClassName(), METHOD_EVENT_SHOULD_COMMIT.getName(), METHOD_EVENT_SHOULD_COMMIT.getDescriptor(), false);
+                 methodVisitor.visitJumpInsn(Opcodes.IFEQ, end);
+                //
                 //   eventHandlerX.write(...);
                 getEventHandler(methodVisitor);
                 methodVisitor.visitTypeInsn(Opcodes.CHECKCAST, eventHandlerXInternalName);
                 for (FieldInfo fi : fieldInfos) {
-                    methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
-                    methodVisitor.visitFieldInsn(Opcodes.GETFIELD, fi.internalClassName, fi.fieldName, fi.fieldDescriptor);
+                   methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
+                   methodVisitor.visitFieldInsn(Opcodes.GETFIELD, fi.internalClassName, fi.fieldName, fi.fieldDescriptor);
                 }
                 methodVisitor.visitMethodInsn(Opcodes.INVOKEVIRTUAL, eventHandlerXInternalName, writeMethod.getName(), writeMethod.getDescriptor(), false);
                 // }
                 methodVisitor.visitLabel(end);
-                methodVisitor.visitFrame(Opcodes.F_SAME, 0, null, 0, null);
                 methodVisitor.visitInsn(Opcodes.RETURN);
                 methodVisitor.visitEnd();
             });
-        } else {
+        }
+
+        if (!streamingCommit) {
             updateMethod(METHOD_COMMIT, methodVisitor -> {
                 // if (!isEnable()) {
                 // return;
@@ -419,8 +473,7 @@
                 Label durationalEvent = new Label();
                 methodVisitor.visitJumpInsn(Opcodes.IFNE, durationalEvent);
                 methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
-                methodVisitor.visitMethodInsn(Opcodes.INVOKESTATIC, TYPE_EVENT_HANDLER.getInternalName(), METHOD_TIME_STAMP.getName(),
-                        METHOD_TIME_STAMP.getDescriptor(), false);
+                methodVisitor.visitMethodInsn(Opcodes.INVOKESTATIC, TYPE_EVENT_HANDLER.getInternalName(), METHOD_TIME_STAMP.getName(), METHOD_TIME_STAMP.getDescriptor(), false);
                 methodVisitor.visitFieldInsn(Opcodes.PUTFIELD, getInternalClassName(), FIELD_START_TIME, "J");
                 Label commit = new Label();
                 methodVisitor.visitJumpInsn(Opcodes.GOTO, commit);
@@ -430,18 +483,18 @@
                 // }
                 methodVisitor.visitLabel(durationalEvent);
                 methodVisitor.visitFrame(Opcodes.F_SAME, 0, null, 0, null);
- //             methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
- //             methodVisitor.visitFieldInsn(Opcodes.GETFIELD, getInternalClassName(), FIELD_DURATION, "J");
- //             methodVisitor.visitInsn(Opcodes.LCONST_0);
- //             methodVisitor.visitInsn(Opcodes.LCMP);
- //             methodVisitor.visitJumpInsn(Opcodes.IFNE, commit);
- //             methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
+                methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
+                methodVisitor.visitFieldInsn(Opcodes.GETFIELD, getInternalClassName(), FIELD_DURATION, "J");
+                methodVisitor.visitInsn(Opcodes.LCONST_0);
+                methodVisitor.visitInsn(Opcodes.LCMP);
+                methodVisitor.visitJumpInsn(Opcodes.IFNE, commit);
+                methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
                 methodVisitor.visitMethodInsn(Opcodes.INVOKESTATIC, TYPE_EVENT_HANDLER.getInternalName(), METHOD_TIME_STAMP.getName(), METHOD_TIME_STAMP.getDescriptor(), false);
                 methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
                 methodVisitor.visitFieldInsn(Opcodes.GETFIELD, getInternalClassName(), FIELD_START_TIME, "J");
                 methodVisitor.visitInsn(Opcodes.LSUB);
                 methodVisitor.visitFieldInsn(Opcodes.PUTFIELD, getInternalClassName(), FIELD_DURATION, "J");
-              methodVisitor.visitLabel(commit);
+                methodVisitor.visitLabel(commit);
                 // if (shouldCommit()) {
                 methodVisitor.visitFrame(Opcodes.F_SAME, 0, null, 0, null);
                 methodVisitor.visitVarInsn(Opcodes.ALOAD, 0);
@@ -503,6 +556,7 @@
         });
     }
 
+
     private void getEventHandler(MethodVisitor methodVisitor) {
         if (untypedEventHandler) {
             methodVisitor.visitFieldInsn(Opcodes.GETSTATIC, getInternalClassName(), FIELD_EVENT_HANDLER, TYPE_OBJECT.getDescriptor());
--- a/test/jdk/jdk/jfr/api/consumer/recordingstream/TestSetEndTime.java	Fri Aug 16 20:50:32 2019 +0200
+++ b/test/jdk/jdk/jfr/api/consumer/recordingstream/TestSetEndTime.java	Thu Aug 22 20:36:52 2019 +0200
@@ -24,6 +24,8 @@
  */
 package jdk.jfr.api.consumer.recordingstream;
 
+import java.nio.file.Path;
+import java.nio.file.Paths;
 import java.time.Duration;
 import java.time.Instant;
 import java.util.concurrent.atomic.AtomicBoolean;
@@ -33,6 +35,8 @@
 import jdk.jfr.Recording;
 import jdk.jfr.StackTrace;
 import jdk.jfr.consumer.EventStream;
+import jdk.jfr.consumer.RecordedEvent;
+import jdk.jfr.consumer.RecordingFile;
 
 /**
  * @test
@@ -54,25 +58,45 @@
         try (Recording r = new Recording()) {
             r.setFlushInterval(Duration.ofSeconds(1));
             r.start();
-            Instant start = Instant.now();
-            System.out.println("Instant.start() = " + start);
-            Thread.sleep(2000);
             Mark event1 = new Mark();
             event1.before = true;
-            event1.commit();
-            Thread.sleep(2000);
-            Instant end = Instant.now();
-            System.out.println("Instant.end() = " + end);
-            Thread.sleep(2000);
+            advanceClock();
+            event1.commit(); // start time
+
             Mark event2 = new Mark();
+            event2.begin();  // end time
+            advanceClock();
+          //  event2.end();
+            Thread.sleep(100);
             event2.before = false;
             event2.commit();
+
+            Path p = Paths.get("recording.jfr");
+            r.dump(p);
+            Instant start = null;
+            Instant end = null;
+            for (RecordedEvent e : RecordingFile.readAllEvents(p)) {
+                if (e.getBoolean("before")) {
+                    start = e.getStartTime();
+                    System.out.println("Start: " + start);
+                }
+                if (!e.getBoolean("before")) {
+                    end = e.getStartTime();
+                    System.out.println("End  : " + end);
+                }
+            }
+
             AtomicBoolean error = new AtomicBoolean(true);
             try (EventStream d = EventStream.openRepository()) {
-                d.setStartTime(start); // needed so we don't start after end time
+                d.setStartTime(start);
                 d.setEndTime(end);
                 d.onEvent(e -> {
                     System.out.println(e);
+                    System.out.println("Event:");
+                    System.out.println(e.getStartTime());
+                    System.out.println(e.getEndTime());
+                    System.out.println(e.getBoolean("before"));
+                    System.out.println();
                     boolean before = e.getBoolean("before");
                     if (before) {
                         error.set(false);
@@ -87,4 +111,12 @@
             }
         }
     }
+
+    private static void advanceClock() {
+        // Wait for some clock movement with
+        // java.time clock resolution.
+        Instant now = Instant.now();
+        while (Instant.now().equals(now)) {
+        }
+    }
 }
\ No newline at end of file