Mercurial > hg > release > thermostat-1.2
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));