Author: athimel Date: 2010-09-27 17:17:42 +0200 (Mon, 27 Sep 2010) New Revision: 1657 Url: http://nuiton.org/repositories/revision/nuiton-utils-extra/1657 Log: Rename LutinTrace to NuitonTrace, and fix some grammar/ortograph errors Added: trunk/src/main/java/org/nuiton/profiling/NuitonTrace.java Removed: trunk/src/main/java/org/nuiton/profiling/LutinTrace.java Modified: trunk/src/site/rst/index.rst Deleted: trunk/src/main/java/org/nuiton/profiling/LutinTrace.java =================================================================== --- trunk/src/main/java/org/nuiton/profiling/LutinTrace.java 2010-09-09 09:30:56 UTC (rev 1656) +++ trunk/src/main/java/org/nuiton/profiling/LutinTrace.java 2010-09-27 15:17:42 UTC (rev 1657) @@ -1,261 +0,0 @@ -/* - * #%L - * Nuiton utilities extra library - * %% - * Copyright (C) 2006 - 2010 CodeLutin - * %% - * This program is free software: you can redistribute it and/or modify - * it under the terms of the GNU Lesser General Public License as - * published by the Free Software Foundation, either version 3 of the - * License, or (at your option) any later version. - * - * This program is distributed in the hope that it will be useful, - * but WITHOUT ANY WARRANTY; without even the implied warranty of - * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the - * GNU General Lesser Public License for more details. - * - * You should have received a copy of the GNU General Lesser Public - * License along with this program. If not, see - * <http://www.gnu.org/licenses/lgpl-3.0.html>. - * #L% - */ -package org.nuiton.profiling; - -import org.apache.commons.lang.time.DurationFormatUtils; -import org.apache.commons.logging.Log; -import org.apache.commons.logging.LogFactory; -import org.codehaus.aspectwerkz.annotation.After; -import org.codehaus.aspectwerkz.annotation.AfterThrowing; -import org.codehaus.aspectwerkz.annotation.Aspect; -import org.codehaus.aspectwerkz.annotation.Before; -import org.codehaus.aspectwerkz.joinpoint.JoinPoint; -import org.codehaus.aspectwerkz.joinpoint.MethodSignature; - -import java.lang.reflect.Method; -import java.util.ArrayList; -import java.util.LinkedHashMap; -import java.util.List; -import java.util.Map; -import java.util.Stack; - -/** - * Permet de tracer les appels aux methodes. - * <p/> - * Pour l'utiliser il faut définir un fichier XML qui intercepte les methodes - * souhaiter. - * <pre> - * <?xml version="1.0" encoding="ISO-8859-1"?> - * <p/> - * <!DOCTYPE aspectwerkz PUBLIC - * "-//AspectWerkz//DTD//EN" - * "http://aspectwerkz.codehaus.org/dtd/aspectwerkz2.dtd">; - * <p/> - * <aspectwerkz> - * <system id="sample"> - * <aspect class="fr.ifremer.isisfish.aspect.TraceIsis"> - * <pointcut name="executeMethod"> - * execution(* fr.ifremer.isisfish.datastore.ResultStorage.*(..)) - * || execution(* fr.ifremer.isisfish.aspect.Cache.*(..)) - * || execution(* fr.ifremer.isisfish.aspect.Trace.*(..)) - * || execution(* org.nuiton.topia..*(..)) - * || execution(* org.nuiton.math.matrix..*(..)) - * || execution(* fr.ifremer.isisfish.types..*(..)) - * || execution(* org.apache.commons.collections..*(..)) - * </pointcut> - * </aspect> - * </system> - * </aspectwerkz> - * <p/> - * </pre> - * Ensuite il faut lancer la JVM avec deux options - * <li> -javaagent:path/to/aspectwerkz-jdk5-2.0.jar - * <li> -Daspectwerkz.definition.file=path/to/trace-aop.xml - * <p/> - * il doit être possible d'utiliser des noms normalisé et - * trouvable dans le classpath a la place de -Daspectwerkz.definition.file - * <li> /aspectwerkz.xml - * <li> META-INF/aop.xml - * <li> WEB-INF/aop.xml - * <p/> - * Ensuite pour afficher les statistiques dans votre programme - * <li> log.info(LutinTrace.getStatistiqueAndClear()); - * <li> LutinTrace.printStatistiqueAndClear(); - * <p/> - * <p/> - * <p/> - * Il doit être possible, plutot que d'écrire un fichier XML, de sous classer - * LutinTrace en ajoutant par exemple - * <p/> - * - * @author poussin - * @Expression( "execution(* fr.ifremer.isisfish.datastore.ResultStorage.*(..))" + - * "|| execution(* fr.ifremer.isisfish.aspect.Cache.*(..))" + - * "|| execution(* fr.ifremer.isisfish.aspect.Trace.*(..))" + - * "|| execution(* org.nuiton.topia..*(..))" + - * "|| execution(* org.nuiton.math.matrix..*(..))" + - * "|| execution(* fr.ifremer.isisfish.types..*(..))" + - * "|| execution(* org.apache.commons.collections..*(..))" - * ) - * Pointcut executeMethod; - * </p> - */ -@Aspect("perJVM") -public class LutinTrace { - - /** to use log facility, just put in your code: log.info("..."); */ - static private Log log = LogFactory.getLog(LutinTrace.class); - - static private List<LutinTrace> instances = new ArrayList<LutinTrace>(); - - /** nombre d'appel */ - final static public int STAT_CALL = 0; - /** nombre d'appel vers une autre method depuis cette methode */ - final static public int STAT_CALL_NEST_METHOD = 1; - /** 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[]> statistiques = new LinkedHashMap<Method, long[]>(); - - /** array : [nest method call, start time, start time with child] */ - protected Stack<long[]> callStack = new Stack<long[]>(); - -// @Expression( -// "execution(* fr.ifremer.isisfish.datastore.ResultStorage.*(..))" + -// "|| execution(* fr.ifremer.isisfish.aspect.Cache.*(..))" + -// "|| execution(* fr.ifremer.isisfish.aspect.Trace.*(..))" + -// "|| execution(* org.nuiton.topia..*(..))" + -// "|| execution(* org.nuiton.math.matrix..*(..))" + -// "|| execution(* fr.ifremer.isisfish.types..*(..))" + -// "|| execution(* org.apache.commons.collections..*(..))" -// ) -// Pointcut executeMethod; - - public LutinTrace() { - instances.add(this); - } - - public long[] getStatistiques(Method method) { - long[] result = statistiques.get(method); - if (result == null) { - result = new long[]{0, 0, 0, 0, 0, 0}; - statistiques.put(method, result); - } - return result; - } - - @Before("executeMethod") - public void traceBeforeExecute(JoinPoint jp) { - // ajout dans le stack - long current = System.nanoTime(); - long[] stackItem = new long[]{0, current, current}; - callStack.push(stackItem); - - - } - - @AfterThrowing("executeMethod") - public void traceAfterThrowingExecute(JoinPoint jp) { - // si une exeption est leve, il faut faire la meme chose - traceAfterExecute(jp); - } - - @After("executeMethod") - public void traceAfterExecute(JoinPoint jp) { - Method method = ((MethodSignature) jp.getSignature()).getMethod(); - - long current = System.nanoTime(); - - 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]; - - long[] stat = getStatistiques(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; - } - if (stat[STAT_TIME_MAX] < timeSpent) { - stat[STAT_TIME_MAX] = 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 :) - } - } - - // ajouter le delta de temps dans le temps passé dans la méthod - - // il faud garder le temps passé dans l'appel d'autre methode de la stack - // --> A - // ========= - // --> B - // <-- B - // ========= - // --> C - // --> D - // <-- D - // <-- C - // ========= - // <-- A - - // le temps reellement passé dans A est representé par les ===== - } - - /** @return les statistiques */ - static public String getStatistiqueAndClear() { - StringBuffer result = new StringBuffer(); - for (LutinTrace trace : instances) { - result.append("--- Statistiques ---\n"); - for (Method method : trace.statistiques.keySet()) { - long[] stat = trace.getStatistiques(method); - long meanTime = stat[STAT_TIME_TOTAL] / stat[STAT_CALL]; - result.append(method + "\t" + - " call: " + stat[STAT_CALL] + - // TIme is in nano not millis, we must divide by 1000000 - " min: " + DurationFormatUtils.formatDuration(stat[STAT_TIME_MIN] / 1000000, "s'.'S") + - " mean: " + DurationFormatUtils.formatDuration(meanTime / 1000000, "s'.'S") + - " max: " + DurationFormatUtils.formatDuration(stat[STAT_TIME_MAX] / 1000000, "s'.'S") + - " total: " + DurationFormatUtils.formatDuration(stat[STAT_TIME_TOTAL] / 1000000, "s'.'S") + - " call_nest: " + stat[STAT_CALL_NEST_METHOD] + - " total_with_nest: " + DurationFormatUtils.formatDuration(stat[STAT_TIME_TOTAL_NEST_METHOD] / 1000000, "s'.'S") + - "\n" - ); - } - result.append("--------------------\n"); - } - instances.clear(); - return result.toString(); - } - - static public void printStatistiqueAndClear() { - String stat = getStatistiqueAndClear(); - if (stat != null && !"".equals(stat)) { - System.out.println(stat); - } - } -} - - Copied: trunk/src/main/java/org/nuiton/profiling/NuitonTrace.java (from rev 1656, trunk/src/main/java/org/nuiton/profiling/LutinTrace.java) =================================================================== --- trunk/src/main/java/org/nuiton/profiling/NuitonTrace.java (rev 0) +++ trunk/src/main/java/org/nuiton/profiling/NuitonTrace.java 2010-09-27 15:17:42 UTC (rev 1657) @@ -0,0 +1,264 @@ +/* + * #%L + * Nuiton utilities extra library + * %% + * Copyright (C) 2006 - 2010 CodeLutin + * %% + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU Lesser General Public License as + * published by the Free Software Foundation, either version 3 of the + * License, or (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Lesser Public License for more details. + * + * You should have received a copy of the GNU General Lesser Public + * License along with this program. If not, see + * <http://www.gnu.org/licenses/lgpl-3.0.html>. + * #L% + */ +package org.nuiton.profiling; + +import org.apache.commons.lang.time.DurationFormatUtils; +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; +import org.codehaus.aspectwerkz.annotation.After; +import org.codehaus.aspectwerkz.annotation.AfterThrowing; +import org.codehaus.aspectwerkz.annotation.Aspect; +import org.codehaus.aspectwerkz.annotation.Before; +import org.codehaus.aspectwerkz.joinpoint.JoinPoint; +import org.codehaus.aspectwerkz.joinpoint.MethodSignature; + +import java.io.PrintStream; +import java.lang.reflect.Method; +import java.util.ArrayList; +import java.util.LinkedHashMap; +import java.util.List; +import java.util.Map; +import java.util.Stack; + +/** + * Permet de tracer les appels aux methodes. + * <p/> + * Pour l'utiliser il faut définir un fichier XML qui intercepte les methodes + * souhaiter. + * <pre> + * <?xml version="1.0" encoding="ISO-8859-1"?> + * <p/> + * <!DOCTYPE aspectwerkz PUBLIC + * "-//AspectWerkz//DTD//EN" + * "http://aspectwerkz.codehaus.org/dtd/aspectwerkz2.dtd">; + * <p/> + * <aspectwerkz> + * <system id="sample"> + * <aspect class="fr.ifremer.isisfish.aspect.TraceIsis"> + * <pointcut name="executeMethod"> + * execution(* fr.ifremer.isisfish.datastore.ResultStorage.*(..)) + * || execution(* fr.ifremer.isisfish.aspect.Cache.*(..)) + * || execution(* fr.ifremer.isisfish.aspect.Trace.*(..)) + * || execution(* org.nuiton.topia..*(..)) + * || execution(* org.nuiton.math.matrix..*(..)) + * || execution(* fr.ifremer.isisfish.types..*(..)) + * || execution(* org.apache.commons.collections..*(..)) + * </pointcut> + * </aspect> + * </system> + * </aspectwerkz> + * <p/> + * </pre> + * Ensuite il faut lancer la JVM avec deux options + * <li> -javaagent:path/to/aspectwerkz-jdk5-2.0.jar + * <li> -Daspectwerkz.definition.file=path/to/trace-aop.xml + * <p/> + * il doit être possible d'utiliser des noms normalisé et + * trouvable dans le classpath a la place de -Daspectwerkz.definition.file + * <li> /aspectwerkz.xml + * <li> META-INF/aop.xml + * <li> WEB-INF/aop.xml + * <p/> + * Ensuite pour afficher les statistiques dans votre programme + * <li> log.info(NuitonTrace.getStatisticsAndClear()); + * <li> NuitonTrace.printStatistiqueAndClear(); + * <p/> + * <p/> + * <p/> + * Il doit être possible, plutot que d'écrire un fichier XML, de sous classer + * NuitonTrace en ajoutant par exemple + * <p/> + * + * @author poussin + * @Expression( "execution(* fr.ifremer.isisfish.datastore.ResultStorage.*(..))" + + * "|| execution(* fr.ifremer.isisfish.aspect.Cache.*(..))" + + * "|| execution(* fr.ifremer.isisfish.aspect.Trace.*(..))" + + * "|| execution(* org.nuiton.topia..*(..))" + + * "|| execution(* org.nuiton.math.matrix..*(..))" + + * "|| execution(* fr.ifremer.isisfish.types..*(..))" + + * "|| execution(* org.apache.commons.collections..*(..))" + * ) + * Pointcut executeMethod; + * </p> + */ +@Aspect("perJVM") +public class NuitonTrace { + + /** to use log facility, just put in your code: log.info("..."); */ + static private Log log = LogFactory.getLog(NuitonTrace.class); + + static private List<NuitonTrace> instances = new ArrayList<NuitonTrace>(); + + /** nombre d'appel */ + final static public int STAT_CALL = 0; + /** nombre d'appel vers une autre method depuis cette methode */ + final static public int STAT_CALL_NEST_METHOD = 1; + /** 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[]>(); + +// @Expression( +// "execution(* fr.ifremer.isisfish.datastore.ResultStorage.*(..))" + +// "|| execution(* fr.ifremer.isisfish.aspect.Cache.*(..))" + +// "|| execution(* fr.ifremer.isisfish.aspect.Trace.*(..))" + +// "|| execution(* org.nuiton.topia..*(..))" + +// "|| execution(* org.nuiton.math.matrix..*(..))" + +// "|| execution(* fr.ifremer.isisfish.types..*(..))" + +// "|| execution(* org.apache.commons.collections..*(..))" +// ) +// Pointcut executeMethod; + + public NuitonTrace() { + instances.add(this); + } + + public long[] getStatistics(Method method) { + long[] result = statistics.get(method); + if (result == null) { + result = new long[]{0, 0, 0, 0, 0, 0}; + statistics.put(method, result); + } + return result; + } + + @Before("executeMethod") + public void traceBeforeExecute(JoinPoint jp) { + // ajout dans le stack + long current = System.nanoTime(); + long[] stackItem = new long[]{0, current, current}; + callStack.push(stackItem); + + + } + + @AfterThrowing("executeMethod") + public void traceAfterThrowingExecute(JoinPoint jp) { + // si une exeption est leve, il faut faire la meme chose + traceAfterExecute(jp); + } + + @After("executeMethod") + public void traceAfterExecute(JoinPoint jp) { + Method method = ((MethodSignature) jp.getSignature()).getMethod(); + + long current = System.nanoTime(); + + 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]; + + 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; + } + if (stat[STAT_TIME_MAX] < timeSpent) { + stat[STAT_TIME_MAX] = 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 :) + } + } + + // ajouter le delta de temps dans le temps passé dans la méthod + + // il faud garder le temps passé dans l'appel d'autre methode de la stack + // --> A + // ========= + // --> B + // <-- B + // ========= + // --> C + // --> D + // <-- D + // <-- C + // ========= + // <-- A + + // le temps reellement passé dans A est representé par les ===== + } + + /** @return les statistiques */ + static public String getStatisticsAndClear() { + StringBuffer result = new StringBuffer(); + 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]; + result.append(method).append("\t") + .append(" call: ").append(stat[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(" 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("\n"); + } + result.append("--------------------\n"); + } + instances.clear(); + return result.toString(); + } + + static public void printStatisticsAndClear() { + printStatisticsAndClear(System.out); + } + + static public void printStatisticsAndClear(PrintStream printer) { + String stat = getStatisticsAndClear(); + if (stat != null && !"".equals(stat)) { + printer.println(stat); + } + } + +} Property changes on: trunk/src/main/java/org/nuiton/profiling/NuitonTrace.java ___________________________________________________________________ Added: svn:keywords + HeadURL Id Date Revision Author Added: svn:eol-style + native Modified: trunk/src/site/rst/index.rst =================================================================== (Binary files differ)