[Nuiton-utils-commits] r2189 - trunk/nuiton-profiling/src/main/java/org/nuiton/profiling

25 Aug 2011

Author: bpoussin
Date: 2011-08-25 16:11:05 +0200 (Thu, 25 Aug 2011)
New Revision: 2189

Url: http://nuiton.org/repositories/revision/nuiton-utils/2189

Log:
Evolution #1712: Add information of caller of method with number of call
- change array of long with java object use as struct

Modified:
   trunk/nuiton-profiling/src/main/java/org/nuiton/profiling/NuitonTrace.java

Modified: trunk/nuiton-profiling/src/main/java/org/nuiton/profiling/NuitonTrace.java
===================================================================

--- trunk/nuiton-profiling/src/main/java/org/nuiton/profiling/NuitonTrace.java	2011-08-24 16:55:22 UTC (rev 2188)
+++ trunk/nuiton-profiling/src/main/java/org/nuiton/profiling/NuitonTrace.java	2011-08-25 14:11:05 UTC (rev 2189)
@@ -21,15 +21,20 @@
  */
 package org.nuiton.profiling;
 
+import java.util.Map.Entry;
 import org.apache.commons.lang.time.DurationFormatUtils;
 
 import java.io.PrintStream;
 import java.lang.reflect.Method;
 import java.util.ArrayList;
+import java.util.Comparator;
+import java.util.HashMap;
 import java.util.LinkedHashMap;
 import java.util.List;
 import java.util.Map;
+import java.util.Set;
 import java.util.Stack;
+import java.util.TreeSet;
 import org.aspectj.lang.JoinPoint;
 import org.aspectj.lang.annotation.After;
 import org.aspectj.lang.annotation.AfterThrowing;
@@ -113,53 +118,48 @@
     /** to use log facility, just put in your code: log.info("..."); */
 //    static private Log log = LogFactory.getLog(NuitonTrace.class);
 
-    /** nombre d'appel */
-    final static public int STAT_CALL = 0;
+    /** array : [call's numbers, call do, min time, max time, total time, total time with child] */
+    protected Map<Method, Statistic> statistics = new LinkedHashMap<Method, Statistic>();
 
-    /** nombre d'appel vers une autre method depuis cette methode */
-    final static public int STAT_CALL_NEST_METHOD = 1;
+    protected Map<Method, Caller<Method>> callers = new HashMap<Method, Caller<Method>>();
 
-    /** temps mini d'execution de cette methode (sans le temps des autres methodes) */
-    final static public int STAT_TIME_MIN = 2;
-
-    /** temps max d'execution de cette methode (sans le temps des autres methodes) */
-    final static public int STAT_TIME_MAX = 3;
-
-    /** temps total d'execution de cette methode (sans le temps des autres methodes) */
-    final static public int STAT_TIME_TOTAL = 4;
-
-    /** temps total d'execution de cette methode (avec le temps des autres methodes) */
-    final static public int STAT_TIME_TOTAL_NEST_METHOD = 5;
-
-    /** nombre d'appel vers une autre method depuis cette methode */
-    final static private int STACK_CALL_NEST_METHOD = 0;
-
-    /** heure de depart de l'appel a la methode (sans le temps des autres methodes) */
-    final static private int STACK_TIME_START = 1;
-
-    /** heure de depart de l'appel a la methode (avec le temps des autres methodes) */
-    final static private int STACK_TIME_START_NEST_METHOD = 2;
-
-
-    /** array : [call's numbers, call do, min time, max time, total time, total time with child] */
-    protected Map<Method, long[]> statistics = new LinkedHashMap<Method, long[]>();
-
     /** array : [nest method call, start time, start time with child] */
-    protected Stack<long[]> callStack = new Stack<long[]>();
+    protected Stack<Call> callStack = new Stack<Call>();
 
     public NuitonTrace() {
         instances.add(this);
     }
 
-    public long[] getStatistics(Method method) {
-        long[] result = statistics.get(method);
+    /**
+     * Retourne les statistiques d'appele pour la methode passee en parametre
+     *
+     * @param method
+     * @return
+     */
+    public Statistic getStatistics(Method method) {
+        Statistic result = statistics.get(method);
         if (result == null) {
-            result = new long[]{0, 0, 0, 0, 0, 0};
+            result = new Statistic(method);
             statistics.put(method, result);
         }
         return result;
     }
 
+    /**
+     * Retourne la liste des appelant pour la methode passee en parametre
+     * 
+     * @param method
+     * @return
+     */
+    public Caller<Method> getCallers(Method method) {
+        Caller<Method> result = callers.get(method);
+        if (result == null) {
+            result = new Caller<Method>();
+            callers.put(method, result);
+        }
+        return result;
+    }
+
     // abstract pointcut: no expression is defined
     @Pointcut
     abstract void executeMethod();
@@ -167,8 +167,10 @@
     @Before("executeMethod()")
     public void traceBeforeExecute(JoinPoint jp) {
         // ajout dans le stack 
+        Method method = ((MethodSignature) jp.getSignature()).getMethod();
         long current = System.nanoTime();
-        long[] stackItem = new long[]{0, current, current};
+
+        Call stackItem = new Call(method, 0, current, current);
         callStack.push(stackItem);
 
 
@@ -189,26 +191,28 @@
         if (callStack.isEmpty()) {
 //            log.warn("Empty stack in afterExecute for method " + method.getName());
         } else {
-            long[] stackItem = callStack.pop();
-            long timeSpent = current - stackItem[STACK_TIME_START];
-            long timeSpentNestMethod = current - stackItem[STACK_TIME_START_NEST_METHOD];
+            Call stackItem = callStack.pop();
+            long timeSpent = current - stackItem.timeStart;
+            long timeSpentNestMethod = current - stackItem.timeStartNestMethod;
 
-            long[] stat = getStatistics(method);
-            stat[STAT_CALL]++; // add +1 to call number
-            stat[STAT_CALL_NEST_METHOD] += stackItem[STACK_CALL_NEST_METHOD];
-            stat[STAT_TIME_TOTAL] += timeSpent;
-            stat[STAT_TIME_TOTAL_NEST_METHOD] += timeSpentNestMethod;
-            if (stat[STAT_TIME_MIN] > timeSpent) {
-                stat[STAT_TIME_MIN] = timeSpent;
+            Statistic stat = getStatistics(method);
+            stat.call++; // add +1 to call number
+            stat.callNestMethod += stackItem.callNestMethod;
+            stat.timeTotal += timeSpent;
+            stat.timeTotalNestMethod += timeSpentNestMethod;
+            if (stat.timeMin > timeSpent) {
+                stat.timeMin = timeSpent;
             }
-            if (stat[STAT_TIME_MAX] < timeSpent) {
-                stat[STAT_TIME_MAX] = timeSpent;
+            if (stat.timeMax < timeSpent) {
+                stat.timeMax = timeSpent;
             }
 
             if (!callStack.isEmpty()) {
-                long[] parent = callStack.peek();
-                parent[STACK_CALL_NEST_METHOD]++;  // add +1 to call number nest method
-                parent[STACK_TIME_START] += timeSpentNestMethod; // remove to time all time spent in nest method (yes + to remove :)
+                Call parent = callStack.peek();
+                parent.callNestMethod++;  // add +1 to call number nest method
+                parent.timeStart += timeSpentNestMethod; // remove to time all time spent in nest method (yes + to remove :)
+
+                getCallers(method).add(parent.method);
             }
         }
 
@@ -241,21 +245,24 @@
                 .append("max;")
                 .append("total;")
                 .append("call_nest;")
-                .append("total_with_nest\n");
+                .append("total_with_nest;")
+                .append("callers;")
+                .append("\n");
         
         for (NuitonTrace trace : instances) {
             for (Method method : trace.statistics.keySet()) {
-                long[] stat = trace.getStatistics(method);
-                long meanTime = stat[STAT_TIME_TOTAL] / stat[STAT_CALL];
+                Statistic stat = trace.getStatistics(method);
+                long meanTime = stat.timeTotal / stat.call;
                 result.append(method)
-                        .append(";").append(stat[STAT_CALL])
+                        .append(";").append(stat.call)
                         // Time is in nano not millis, we must divide by 1000000
-                        .append(";").append(DurationFormatUtils.formatDuration(stat[STAT_TIME_MIN] / 1000000, "s'.'S"))
+                        .append(";").append(DurationFormatUtils.formatDuration(stat.timeMin / 1000000, "s'.'S"))
                         .append(";").append(DurationFormatUtils.formatDuration(meanTime / 1000000, "s'.'S"))
-                        .append(";").append(DurationFormatUtils.formatDuration(stat[STAT_TIME_MAX] / 1000000, "s'.'S"))
-                        .append(";").append(DurationFormatUtils.formatDuration(stat[STAT_TIME_TOTAL] / 1000000, "s'.'S"))
-                        .append(";").append(stat[STAT_CALL_NEST_METHOD])
-                        .append(";").append(DurationFormatUtils.formatDuration(stat[STAT_TIME_TOTAL_NEST_METHOD] / 1000000, "s'.'S"))
+                        .append(";").append(DurationFormatUtils.formatDuration(stat.timeMax / 1000000, "s'.'S"))
+                        .append(";").append(DurationFormatUtils.formatDuration(stat.timeTotal / 1000000, "s'.'S"))
+                        .append(";").append(stat.callNestMethod)
+                        .append(";").append(DurationFormatUtils.formatDuration(stat.timeTotalNestMethod / 1000000, "s'.'S"))
+                        .append(";").append(trace.getCallers(method))
                         .append("\n");
             }
         }
@@ -269,17 +276,18 @@
         for (NuitonTrace trace : instances) {
             result.append("--- Statistics ---\n");
             for (Method method : trace.statistics.keySet()) {
-                long[] stat = trace.getStatistics(method);
-                long meanTime = stat[STAT_TIME_TOTAL] / stat[STAT_CALL];
+                Statistic stat = trace.getStatistics(method);
+                long meanTime = stat.timeTotal / stat.call;
                 result.append(method).append("\t")
-                        .append(" call: ").append(stat[STAT_CALL])
+                        .append(" call: ").append(stat.call)
                         // TIme is in nano not millis, we must divide by 1000000
-                        .append(" min: ").append(DurationFormatUtils.formatDuration(stat[STAT_TIME_MIN] / 1000000, "s'.'S"))
+                        .append(" min: ").append(DurationFormatUtils.formatDuration(stat.timeMin / 1000000, "s'.'S"))
                         .append(" mean: ").append(DurationFormatUtils.formatDuration(meanTime / 1000000, "s'.'S"))
-                        .append(" max: ").append(DurationFormatUtils.formatDuration(stat[STAT_TIME_MAX] / 1000000, "s'.'S"))
-                        .append(" total: ").append(DurationFormatUtils.formatDuration(stat[STAT_TIME_TOTAL] / 1000000, "s'.'S"))
-                        .append(" call_nest: ").append(stat[STAT_CALL_NEST_METHOD])
-                        .append(" total_with_nest: ").append(DurationFormatUtils.formatDuration(stat[STAT_TIME_TOTAL_NEST_METHOD] / 1000000, "s'.'S"))
+                        .append(" max: ").append(DurationFormatUtils.formatDuration(stat.timeMax / 1000000, "s'.'S"))
+                        .append(" total: ").append(DurationFormatUtils.formatDuration(stat.timeTotal / 1000000, "s'.'S"))
+                        .append(" call_nest: ").append(stat.callNestMethod)
+                        .append(" total_with_nest: ").append(DurationFormatUtils.formatDuration(stat.timeTotalNestMethod / 1000000, "s'.'S"))
+                        .append(" callers: ").append(trace.getCallers(method))
                         .append("\n");
             }
             result.append("--------------------\n");
@@ -299,4 +307,112 @@
         }
     }
 
+    /**
+     * Statistique sur un appele de methode
+     */
+    protected static class Statistic {
+        Method method;
+        /** nombre d'appel */
+        long call = 0;
+        /** nombre d'appel vers une autre method depuis cette methode */
+        long callNestMethod = 0;
+        /** temps mini d'execution de cette methode (sans le temps des autres methodes) */
+        long timeMin = 0;
+        /** temps max d'execution de cette methode (sans le temps des autres methodes) */
+        long timeMax = 0;
+        /** temps total d'execution de cette methode (sans le temps des autres methodes) */
+        long timeTotal = 0;
+        /** temps total d'execution de cette methode (avec le temps des autres methodes) */
+        long timeTotalNestMethod = 0;
+
+        public Statistic(Method method) {
+            this.method = method;
+        }
+
+    }
+
+    /**
+     * Represente un call de methode
+     */
+    protected static class Call {
+        Method method;
+        /** nombre d'appel vers une autre method depuis cette methode */
+        long callNestMethod;
+        /** heure de depart de l'appel a la methode (sans le temps des autres methodes) */
+        long timeStart;
+        /** heure de depart de l'appel a la methode (avec le temps des autres methodes) */
+        long timeStartNestMethod;
+
+        public Call(Method method, long callNestMethod, long timeStart, long timeStartNestMethod) {
+            this.method = method;
+            this.callNestMethod = callNestMethod;
+            this.timeStart = timeStart;
+            this.timeStartNestMethod = timeStartNestMethod;
+        }
+
+    }
+
+    /**
+     * Classe qui permet d'ajouter un element et compte le nombre de fois
+     * que l'on a ajoute cet element.
+     * 
+     * exemple d'utilisation: on souhaite compter le nombre de fois qu'une methode
+     * est appeler par une autre, on ajoute a chaque fois que quelqu'un fait
+     * appele a elle ce quelqu'un.
+     * 
+     */
+    protected static class Caller<E> {
+
+        protected Map<E, Integer> data = new HashMap<E, Integer>();
+        
+        /**
+         * indique que l'on ajoute un element
+         * @param e
+         */
+        public void add(E e) {
+            Integer v = data.get(e);
+            if (v == null) {
+                v = 0;
+            }
+            data.put(e, v+1);
+        }
+
+        /**
+         * Retourne la liste des objets ajouter avec le nombre de fois qu'ils
+         * ont ete ajoute. Trie par le nombre de fois qu'ils ont ete ajoute,le
+         * plus grand nombre en 1er
+         * 
+         * @return
+         */
+        @Override
+        public String toString() {
+            Comparator<Map.Entry<E, Integer>> comparator = new Comparator<Map.Entry<E, Integer>>() {
+                public int compare(Entry<E, Integer> o1, Entry<E, Integer> o2) {
+                    // on inverse, car on veut le plus grand en 1er
+                    return o2.getValue().compareTo(o1.getValue());
+                }
+            };
+
+            Set<Map.Entry<E, Integer>> entries = data.entrySet();
+            Set<Map.Entry<E, Integer>> sorted = 
+                    new TreeSet<Map.Entry<E, Integer>>(comparator);
+            sorted.addAll(entries);
+
+            StringBuilder result = new StringBuilder();
+
+            for (Map.Entry<E, Integer> e : sorted) {
+                result.append(e.getValue()).append("=[").append(e.getKey()).append("]").append(",");
+            }
+            if (result.length() > 0) {
+                // on supprime la derniere virgule en trop
+                result.deleteCharAt(result.length()-1);
+            }
+
+            return result.toString();
+        }
+
+
+
+    }
+
 }

    

[Nuiton-utils-commits] r2189 - trunk/nuiton-profiling/src/main/java/org/nuiton/profiling

bpoussin＠users.nuiton.org