Moving to root below branch label

git-svn-id: https://svn.alfresco.com/repos/alfresco-enterprise/alfresco/HEAD/root@2005 c4b6b30b-aa2e-2d43-bbcb-ca4b014f7261

source/java/org/alfresco/util/perf/AbstractPerformanceMonitor.java

@@ -0,0 +1,194 @@
+/*
+ * Copyright (C) 2005 Alfresco, Inc.
+ *
+ * Licensed under the Mozilla Public License version 1.1 
+ * with a permitted attribution clause. You may obtain a
+ * copy of the License at
+ *
+ *   http://www.alfresco.org/legal/license.txt
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND,
+ * either express or implied. See the License for the specific
+ * language governing permissions and limitations under the
+ * License.
+ */
+package org.alfresco.util.perf;
+
+import java.text.DecimalFormat;
+import java.util.Set;
+import java.util.SortedMap;
+import java.util.TreeMap;
+
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+
+/**
+ * An instance of this class keeps track of timings of method calls made against
+ * a named entity.  Logging can occur either after each recorded time, or only on
+ * VM shutdown or both.
+ * <p>
+ * Logging output is managed down to either the entity or entity-invocation level as follows:
+ * <p>
+ * <pre>
+ *      performance.summary.method
+ *      performance.summary.vm
+ *          AND
+ *      performance.targetEntityName
+ *      performance.targetEntityName.methodName
+ * </pre>
+ * <p>
+ * The following examples illustrate how it can be used:
+ * <p>
+ * <pre>
+ *      performance.summary.method=DEBUG
+ *      performance.myBean=DEBUG
+ *          --> Output method invocation statistic on each call to myBean
+ *          
+ *      performance.summary.vm=DEBUG
+ *      performance.myBean.doSomething=DEBUG
+ *          --> Output summary for doSomething() invocations on myBean when VM terminates
+ * 
+ *      performance=DEBUG
+ *          --> Output all performance data - after each invocation and upon VM closure          
+ * </pre>
+ * <p>
+ * 
+ * @author Derek Hulley
+ */
+public abstract class AbstractPerformanceMonitor
+{
+    /** logger for method level performance summaries */
+    private static final Log methodSummaryLogger = LogFactory.getLog("performance.summary.method");
+    /** logger for VM level performance summaries */
+    private static final Log vmSummaryLogger = LogFactory.getLog("performance.summary.vm");
+    
+    private final String entityName;
+    /** VM level summary */
+    private SortedMap<String, MethodStats> stats;
+
+    /**
+     * Convenience method to check if there is some sort of performance logging enabled
+     * 
+     * @return Returns true if there is some sort of performance logging enabled, false otherwise
+     */
+    public static boolean isDebugEnabled()
+    {
+        return (vmSummaryLogger.isDebugEnabled() || methodSummaryLogger.isDebugEnabled());
+    }
+    
+    /**
+     * @param entityName the name of the entity for which the performance is being recorded 
+     */
+    public AbstractPerformanceMonitor(String entityName)
+    {
+        this.entityName = entityName;
+        stats = new TreeMap<String, MethodStats>();
+        
+        // enable a VM shutdown hook if required
+        if (vmSummaryLogger.isDebugEnabled())
+        {
+            Thread hook = new ShutdownThread();
+            Runtime.getRuntime().addShutdownHook(hook);
+        }
+    }
+    
+    /**
+     * Dumps the results of the method execution to:
+     * <ul>
+     *   <li>DEBUG output if the method level debug logging is active</li>
+     *   <li>Performance store if required</li>
+     * </ul>
+     * 
+     * @param methodName the name of the method against which to store the results
+     * @param delayMs
+     */
+    protected void recordStats(String methodName, double delayMs)
+    {
+        Log methodLogger = LogFactory.getLog("performance." + entityName + "." + methodName);
+        if (!methodLogger.isDebugEnabled())
+        {
+            // no recording for this method
+            return;
+        }
+
+        DecimalFormat format = new DecimalFormat ();
+        format.setMinimumFractionDigits (3);
+        format.setMaximumFractionDigits (3);
+
+        // must we log on a per-method call?
+        if (methodSummaryLogger.isDebugEnabled())
+        {
+            methodLogger.debug("Executed " + entityName + "#" + methodName + " in " + format.format(delayMs) + "ms");
+        }
+        if (vmSummaryLogger.isDebugEnabled())
+        {
+            synchronized(this)  // only synchronize if absolutely necessary
+            {
+                // get stats
+                MethodStats methodStats = stats.get(methodName);
+                if (methodStats == null)
+                {
+                    methodStats = new MethodStats();
+                    stats.put(methodName, methodStats);
+                }
+                methodStats.record(delayMs);
+            }
+        }
+    }
+    
+    /**
+     * Stores the execution count and total execution time for any method 
+     */
+    private class MethodStats
+    {
+        private int count;
+        private double totalTimeMs;
+        
+        /**
+         * Records the time for a method to execute and bumps up the execution count
+         * 
+         * @param delayMs the time the method took to execute in milliseconds
+         */
+        public void record(double delayMs)
+        {
+           count++;
+           totalTimeMs += delayMs;
+        }
+        
+        public String toString()
+        {
+            DecimalFormat format = new DecimalFormat ();
+            format.setMinimumFractionDigits (3);
+            format.setMaximumFractionDigits (3);
+            double averageMs = totalTimeMs / (long) count;
+            return ("Executed " + count + " times, averaging " + format.format(averageMs) + "ms per call");
+        }
+    }
+    
+    /**
+     * Dumps the output of all recorded method statistics
+     */
+    private class ShutdownThread extends Thread
+    {
+        public void run()
+        {
+            String beanName = AbstractPerformanceMonitor.this.entityName;
+            
+            // prevent multiple ShutdownThread instances interleaving their output
+            synchronized(ShutdownThread.class)
+            {
+                vmSummaryLogger.debug("\n==================== " + beanName.toUpperCase() + " ===================");
+                Set<String> methodNames = stats.keySet();
+                for (String methodName : methodNames)
+                {
+                    vmSummaryLogger.debug("\nMethod performance summary: \n" +
+                            "   Bean: " + AbstractPerformanceMonitor.this.entityName + "\n" +
+                            "   Method: " + methodName + "\n" +
+                            "   Statistics: " + stats.get(methodName));
+                }
+            }
+        }
+    }
+}

source/java/org/alfresco/util/perf/PerformanceMonitor.java

@@ -0,0 +1,119 @@
+/*
+ * Copyright (C) 2005 Alfresco, Inc.
+ *
+ * Licensed under the Mozilla Public License version 1.1 
+ * with a permitted attribution clause. You may obtain a
+ * copy of the License at
+ *
+ *   http://www.alfresco.org/legal/license.txt
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND,
+ * either express or implied. See the License for the specific
+ * language governing permissions and limitations under the
+ * License.
+ */
+package org.alfresco.util.perf;
+
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+
+import com.vladium.utils.timing.ITimer;
+import com.vladium.utils.timing.TimerFactory;
+
+/**
+ * Enables <b>begin ... end</b> style performance monitoring with summarisation
+ * using the <b>performance</b> logging category.  It is designed to only incur
+ * a minor cost when performance logging is turned on using the DEBUG logging
+ * mechanism.  See base class for details on enabling the <b>performance</b>
+ * logging categories.
+ * <p>
+ * This class is thread safe.
+ * <p>
+ * Usage:
+ * <pre>
+ * private PerformanceMonitor somethingTimer = new PerformanceMonitor("mytest", "doSomething");
+ * ...
+ * ...
+ * private void doSomething()
+ * {
+ *    somethingTimer.start();
+ *    ...
+ *    ...
+ *    somethingTimer.stop();
+ * }
+ * </pre>
+ * 
+ * @author Derek Hulley
+ */
+public class PerformanceMonitor extends AbstractPerformanceMonitor
+{
+    private String methodName;
+    private ThreadLocal<ITimer> threadLocalTimer;
+    private boolean log;
+    
+    /**
+     * @param entityName name of the entity, e.g. a test name or a bean name against which to
+     *      log the performance
+     * @param methodName the method for which the performance will be logged
+     */
+    public PerformanceMonitor(String entityName, String methodName)
+    {
+        super(entityName);
+        this.methodName = methodName;
+        this.threadLocalTimer = new ThreadLocal<ITimer>();
+        
+        // check if logging can be eliminated
+        Log methodLogger = LogFactory.getLog("performance." + entityName + "." + methodName);
+        this.log = AbstractPerformanceMonitor.isDebugEnabled() && methodLogger.isDebugEnabled();  
+    }
+    
+    /**
+     * Threadsafe method to start the timer.
+     * <p>
+     * The timer is only started if the logging levels are enabled.
+     * 
+     * @see #stop()
+     */
+    public void start()
+    {
+        if (!log)
+        {
+            // don't bother timing
+            return;
+        }
+        // overwrite the thread's timer
+        ITimer timer = TimerFactory.newTimer();
+        threadLocalTimer.set(timer);
+        // start the timer
+        timer.start();
+    }
+    
+    /**
+     * Threadsafe method to stop the timer.
+     * 
+     * @see #start()
+     */
+    public void stop()
+    {
+        if (!log)
+        {
+            // don't bother timing
+            return;
+        }
+        // get the thread's timer
+        ITimer timer = threadLocalTimer.get();
+        if (timer == null)
+        {
+            // begin not called on the thread
+            return;
+        }
+        // time it
+        timer.stop();
+        recordStats(methodName, timer.getDuration());
+        
+        // drop the thread's timer
+        threadLocalTimer.set(null);
+    }
+}

source/java/org/alfresco/util/perf/PerformanceMonitorAdvice.java

@@ -0,0 +1,70 @@
+/*
+ * Copyright (C) 2005 Alfresco, Inc.
+ *
+ * Licensed under the Mozilla Public License version 1.1 
+ * with a permitted attribution clause. You may obtain a
+ * copy of the License at
+ *
+ *   http://www.alfresco.org/legal/license.txt
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND,
+ * either express or implied. See the License for the specific
+ * language governing permissions and limitations under the
+ * License.
+ */
+package org.alfresco.util.perf;
+
+import org.aopalliance.intercept.MethodInterceptor;
+import org.aopalliance.intercept.MethodInvocation;
+
+import com.vladium.utils.timing.ITimer;
+import com.vladium.utils.timing.TimerFactory;
+
+/**
+ * An instance of this class keeps track of timings of method calls on a bean
+ * 
+ * @author Derek Hulley
+ */
+public class PerformanceMonitorAdvice extends AbstractPerformanceMonitor implements MethodInterceptor
+{
+    public PerformanceMonitorAdvice(String beanName)
+    {
+        super(beanName);
+    }
+    
+    public Object invoke(MethodInvocation invocation) throws Throwable
+    {
+        // bypass all recording if performance logging is not required
+        if (AbstractPerformanceMonitor.isDebugEnabled())
+        {
+            return invokeWithLogging(invocation);
+        }
+        else
+        {
+            // no logging required
+            return invocation.proceed();
+        }
+    }
+    
+    private Object invokeWithLogging(MethodInvocation invocation) throws Throwable
+    {
+        // get the time prior to call
+        ITimer timer = TimerFactory.newTimer ();
+        
+        timer.start ();
+
+        //long start = System.currentTimeMillis();
+        // execute - do not record exceptions
+        Object ret = invocation.proceed();
+        // get time after call
+        //long end = System.currentTimeMillis();
+        // record the stats
+        timer.stop ();
+       
+        recordStats(invocation.getMethod().getName(),  timer.getDuration ());
+        // done
+        return ret;
+    }
+}

source/java/org/alfresco/util/perf/PerformanceMonitorTest.java

@@ -0,0 +1,55 @@
+/*
+ * Copyright (C) 2005 Alfresco, Inc.
+ *
+ * Licensed under the Mozilla Public License version 1.1 
+ * with a permitted attribution clause. You may obtain a
+ * copy of the License at
+ *
+ *   http://www.alfresco.org/legal/license.txt
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND,
+ * either express or implied. See the License for the specific
+ * language governing permissions and limitations under the
+ * License.
+ */
+package org.alfresco.util.perf;
+
+import java.lang.reflect.Method;
+
+import junit.framework.TestCase;
+
+/**
+ * Enabled vm performance monitoring for <b>performance.summary.vm</b> and
+ * <b>performance.PerformanceMonitorTest</b> to check.
+ * 
+ * @see org.alfresco.util.perf.PerformanceMonitor
+ * 
+ * @author Derek Hulley
+ */
+public class PerformanceMonitorTest extends TestCase
+{
+    private PerformanceMonitor testTimingMonitor;
+    
+    @Override
+    public void setUp() throws Exception
+    {
+        Method testTimingMethod = PerformanceMonitorTest.class.getMethod("testTiming");
+        testTimingMonitor = new PerformanceMonitor("PerformanceMonitorTest", "testTiming");
+    }
+    
+    public void testSetUp() throws Exception
+    {
+        assertNotNull(testTimingMonitor);
+    }
+    
+    public synchronized void testTiming() throws Exception
+    {
+        testTimingMonitor.start();
+        
+        wait(50);
+        
+        testTimingMonitor.stop();
+    }
+}