changeset 1563:67f51a18294b

Record non-cumulative times during profiling Reviewed-by: neugens Review-thread: http://icedtea.classpath.org/pipermail/thermostat/2014-November/011674.html
author Omair Majid <omajid@redhat.com>
date Mon, 24 Nov 2014 13:12:40 -0500
parents dee75542747f
children 6a6dbf86e717
files vm-profiler/client-swing/src/main/resources/com/redhat/thermostat/vm/profiler/client/swing/internal/strings.properties vm-profiler/jvm-agent/src/main/java/com/redhat/thermostat/vm/profiler/agent/jvm/AsmBasedInstrumentor.java vm-profiler/jvm-agent/src/main/java/com/redhat/thermostat/vm/profiler/agent/jvm/ProfileRecorder.java
diffstat 3 files changed, 79 insertions(+), 16 deletions(-) [+]
line wrap: on
line diff
--- a/vm-profiler/client-swing/src/main/resources/com/redhat/thermostat/vm/profiler/client/swing/internal/strings.properties	Mon Nov 24 13:12:39 2014 -0500
+++ b/vm-profiler/client-swing/src/main/resources/com/redhat/thermostat/vm/profiler/client/swing/internal/strings.properties	Mon Nov 24 13:12:40 2014 -0500
@@ -7,4 +7,4 @@
 
 PROFILER_LIST_ITEM = Session @ {1} ({0})
 PROFILER_RESULTS_METHOD = Method
-PROFILER_RESULTS_TIME = Cumulative Time ({0})
\ No newline at end of file
+PROFILER_RESULTS_TIME = Total Time ({0})
--- a/vm-profiler/jvm-agent/src/main/java/com/redhat/thermostat/vm/profiler/agent/jvm/AsmBasedInstrumentor.java	Mon Nov 24 13:12:39 2014 -0500
+++ b/vm-profiler/jvm-agent/src/main/java/com/redhat/thermostat/vm/profiler/agent/jvm/AsmBasedInstrumentor.java	Mon Nov 24 13:12:40 2014 -0500
@@ -98,9 +98,6 @@
     }
 
     static class InstrumentingMethodAdapter extends AdviceAdapter {
-
-        private int time;
-
         private String className;
         private String methodName;
 
@@ -113,22 +110,18 @@
 
         @Override
         protected void onMethodEnter() {
-            mv.visitMethodInsn(Opcodes.INVOKESTATIC, "java/lang/System", "nanoTime", "()J", false);
-            time = newLocal(Type.LONG_TYPE);
-            mv.visitVarInsn(Opcodes.LSTORE, time);
+            callProfilerRecorder("enterMethod");
         }
 
         @Override
         protected void onMethodExit(int opCode) {
-            mv.visitMethodInsn(Opcodes.INVOKESTATIC, "java/lang/System", "nanoTime", "()J", false);
-            mv.visitVarInsn(Opcodes.LLOAD, time);
-            mv.visitInsn(Opcodes.LSUB);
-            int diff = newLocal(Type.LONG_TYPE);
-            mv.visitVarInsn(Opcodes.LSTORE, diff);
+            callProfilerRecorder("exitMethod");
+        }
+
+        private void callProfilerRecorder(String method) {
             mv.visitMethodInsn(Opcodes.INVOKESTATIC, RECORDER_CLASS_NAME, "getInstance", "()L" + RECORDER_CLASS_NAME + ";", false);
             mv.visitLdcInsn(className + "." + methodName + methodDesc);
-            mv.visitVarInsn(Opcodes.LLOAD, diff);
-            mv.visitMethodInsn(Opcodes.INVOKEVIRTUAL, RECORDER_CLASS_NAME, "addData", "(Ljava/lang/String;J)V", false);
+            mv.visitMethodInsn(Opcodes.INVOKEVIRTUAL, RECORDER_CLASS_NAME, method, "(Ljava/lang/String;)V", false);
         }
 
         // for debugging: insert opcodes to invoke System.exit()
--- a/vm-profiler/jvm-agent/src/main/java/com/redhat/thermostat/vm/profiler/agent/jvm/ProfileRecorder.java	Mon Nov 24 13:12:39 2014 -0500
+++ b/vm-profiler/jvm-agent/src/main/java/com/redhat/thermostat/vm/profiler/agent/jvm/ProfileRecorder.java	Mon Nov 24 13:12:40 2014 -0500
@@ -36,7 +36,11 @@
 
 package com.redhat.thermostat.vm.profiler.agent.jvm;
 
+import java.util.ArrayDeque;
+import java.util.Deque;
 import java.util.Map;
+import java.util.Objects;
+import java.util.Queue;
 import java.util.concurrent.ConcurrentHashMap;
 import java.util.concurrent.atomic.AtomicLong;
 
@@ -44,13 +48,79 @@
 
     private static final ProfileRecorder profileRecorder = new ProfileRecorder();
 
-    private ConcurrentHashMap<String,AtomicLong> profileData = new ConcurrentHashMap<>();
+    /** shared between threads */
+    private ConcurrentHashMap<String, AtomicLong> profileData = new ConcurrentHashMap<>();
+
+    // TODO deal with thread id wrap-around
+
+    /**
+     * thread id -> info.
+     * <p>
+     * only the thread with the matching thread id is allowed to mutate 'info'
+     */
+    private Map<Long, Info> threads = new ConcurrentHashMap<>();
+
+    final static class Info {
+        public Deque<String> stackFrames = new ArrayDeque<>();
+        public long timeStamp = Long.MIN_VALUE;
+    }
 
     public static ProfileRecorder getInstance() {
         return profileRecorder;
     }
 
-    public void addData(String dataName, long time) {
+    /** called by instrumented code on every method enter */
+    public void enterMethod(String fullyQualifiedName) {
+        Objects.requireNonNull(fullyQualifiedName);
+
+        long currentTime = System.nanoTime();
+        long threadId = Thread.currentThread().getId();
+
+        Info info = threads.get(threadId);
+
+        if (info == null) {
+            info = new Info();
+            threads.put(threadId, info);
+        }
+
+        if (info.stackFrames.size() != 0) {
+            // update time for previous method on the stack
+            Long oldTime = info.timeStamp;
+            long diff = currentTime - oldTime;
+            addData(info.stackFrames.peek(), diff);
+        }
+
+        info.timeStamp = currentTime;
+        info.stackFrames.push(fullyQualifiedName);
+    }
+
+    /** called by instrumented code on every method exit */
+    public void exitMethod(String fullyQualifiedName) {
+        Objects.requireNonNull(fullyQualifiedName);
+
+        long currentTime = System.nanoTime();
+        long threadId = Thread.currentThread().getId();
+
+        Info info = threads.get(threadId);
+        Queue<String> stack = info.stackFrames;
+
+        Long oldTime = info.timeStamp;
+        long diff = currentTime - oldTime;
+
+        if (!fullyQualifiedName.equals(stack.peek())) {
+            System.out.println("name: '" + fullyQualifiedName + "'");
+            System.out.println("stack top: '" + stack.peek() + "'");
+            System.out.println("stack: " + stack);
+            throw new AssertionError("should not happen");
+        }
+
+        addData(stack.poll(), diff);
+
+        info.timeStamp = currentTime;
+    }
+
+    private void addData(String dataName, long time) {
+        Objects.requireNonNull(dataName);
         AtomicLong value = profileData.get(dataName);
         if (value == null) {
             value = profileData.putIfAbsent(dataName, new AtomicLong(time));