<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration debug="false" xmlns:log4j="http://jakarta.apache.org/log4j/">
    <!--
      This default ConsoleAppender is used to log all NON jperf messages
      to System.out
    -->
    <appender name="console" class="org.apache.log4j.ConsoleAppender">
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%-5p %c{1} - %m%n"/>
        </layout>
    </appender>

    <!-- JPerf appenders -->
    <!--
      This AsyncCoalescingStatisticsAppender groups StopWatch log messages
      into GroupedTimingStatistics messages which it sends on the
      file appender defined below
    -->
    <appender name="CoalescingStatistics"
              class="net.jperf.log4j.AsyncCoalescingStatisticsAppender">
        <!--
          The TimeSlice option is used to determine the time window for which
          all received StopWatch logs are aggregated to create a single
          GroupedTimingStatistics log. Here we set it to 10 seconds, overriding
          the default of 30000 ms
        -->
        <param name="TimeSlice" value="10000"/>
        <appender-ref ref="fileAppender"/>
        <!--
          Note how the GraphingStatisticsAppenders have been attached to the
          CoalescingStatistics here.
        -->
        <appender-ref ref="graphExecutionTimes"/>
        <appender-ref ref="graphExecutionTPS"/>
    </appender>

    <!-- This file appender is used to output aggregated performance statistics -->
    <appender name="fileAppender" class="org.apache.log4j.FileAppender">
        <param name="File" value="perfStats.log"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%m%n"/>
        </layout>
    </appender>

    <!--
      This first GraphingStatisticsAppender graphs Mean execution times for the
      firstBlock and secondBlock tags
    -->
    <appender name="graphExecutionTimes"
              class="net.jperf.log4j.GraphingStatisticsAppender">
        <!-- Possible GraphTypes are Mean, Min, Max, StdDev, Count and TPS -->
        <param name="GraphType" value="Mean"/>
        <!-- The tags of the timed execution blocks to graph are specified here -->
        <param name="TagNamesToGraph" value="firstBlock,secondBlock"/>
        <appender-ref ref="graphsFileAppender"/>
    </appender>

    <!--
      This second GraphingStatisticsAppender graphs transactions per second
      for the firstBlock and secondBlock tags
    -->
    <appender name="graphExecutionTPS"
              class="net.jperf.log4j.GraphingStatisticsAppender">
        <param name="GraphType" value="TPS"/>
        <param name="TagNamesToGraph" value="firstBlock,secondBlock"/>
        <appender-ref ref="graphsFileAppender"/>
    </appender>

    <!--
      This file appender is used to output the graph URLs generated
      by the GraphingStatisticsAppenders
    -->
    <appender name="graphsFileAppender" class="org.apache.log4j.FileAppender">
        <param name="File" value="perfGraphs.log"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%m%n"/>
        </layout>
    </appender>

    <!-- Loggers -->
    <!--
      The JPerf logger. Note that net.jperfTimingLogger is the value of the
      net.jperfStopWatch.DEFAULT_LOGGER_NAME constant. Also, note that
      additivity is set to false, which is usually what is desired - this means
      that timing statements will only be sent to this logger and NOT to
      upstream loggers.
    -->
    <logger name="net.jperf.TimingLogger" additivity="false">
        <level value="INFO"/>
        <appender-ref ref="CoalescingStatistics"/>
    </logger>

    <!--
      The root logger sends all log statements EXCEPT those sent to the jperf
      logger to System.out.
    -->
    <root>
        <level value="INFO"/>
        <appender-ref ref="console"/>
    </root>
</log4j:configuration>

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration debug="false" xmlns:log4j="http://jakarta.apache.org/log4j/">
    <!--
      This default ConsoleAppender is used to log all NON jperf messages
      to System.out
    -->
    <appender name="console" class="org.apache.log4j.ConsoleAppender">
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%-5p %c{1} - %m%n"/>
        </layout>
    </appender>

    <!-- JPerf appenders -->
    <!--
      This AsyncCoalescingStatisticsAppender groups StopWatch log messages
      into GroupedTimingStatistics messages which it sends on the
      file appender defined below
    -->
    <appender name="CoalescingStatistics"
              class="net.jperf.log4j.AsyncCoalescingStatisticsAppender">
        <!--
          The TimeSlice option is used to determine the time window for which
          all received StopWatch logs are aggregated to create a single
          GroupedTimingStatistics log. Here we set it to 10 seconds, overriding
          the default of 30000 ms
        -->
        <param name="TimeSlice" value="10000"/>
        <appender-ref ref="fileAppender"/>
        <appender-ref ref="graphExecutionTimes"/>
        <appender-ref ref="graphExecutionTPS"/>
        <!-- We add the JMX Appender reference onto the CoalescingStatistics -->
        <appender-ref ref="jperfJmxAppender"/>
    </appender>

    <!-- This file appender is used to output aggregated performance statistics -->
    <appender name="fileAppender" class="org.apache.log4j.FileAppender">
        <param name="File" value="perfStats.log"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%m%n"/>
        </layout>
    </appender>

    <!--
      This first GraphingStatisticsAppender graphs Mean execution times for the
      firstBlock and secondBlock tags
    -->
    <appender name="graphExecutionTimes"
              class="net.jperf.log4j.GraphingStatisticsAppender">
        <!-- Possible GraphTypes are Mean, Min, Max, StdDev, Count and TPS -->
        <param name="GraphType" value="Mean"/>
        <!-- The tags of the timed execution blocks to graph are specified here -->
        <param name="TagNamesToGraph" value="firstBlock,secondBlock"/>
        <appender-ref ref="graphsFileAppender"/>
    </appender>

    <!--
      This second GraphingStatisticsAppender graphs transactions per second
      for the firstBlock and secondBlock tags
    -->
    <appender name="graphExecutionTPS"
              class="net.jperf.log4j.GraphingStatisticsAppender">
        <param name="GraphType" value="TPS"/>
        <param name="TagNamesToGraph" value="firstBlock,secondBlock"/>
        <appender-ref ref="graphsFileAppender"/>
    </appender>

    <!--
      This file appender is used to output the graph URLs generated
      by the GraphingStatisticsAppenders
    -->
    <appender name="graphsFileAppender" class="org.apache.log4j.FileAppender">
        <param name="File" value="perfGraphs.log"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%m%n"/>
        </layout>
    </appender>

    <!--
      This JMX appender creates an MBean and publishes it to the platform MBean server by
      default.
    -->
    <appender name="jperfJmxAppender" class="net.jperf.log4j.JmxAttributeStatisticsAppender">
        <!--
          You must specify the tag names whose statistics should be exposed as
          MBean attributes.
        -->
        <param name="TagNamesToExpose" value="firstBlock,secondBlock"/>
        <!--
          The NotificationThresholds param configures the sending of JMX notifications
          when statistic values exceed specified thresholds. This config states that
          the firstBlock max value should be between 0 and 800ms, and the secondBlock max
          value should be less than 1500 ms. You can also set thresholds on the Min,
          Mean, StdDev, Count and TPS statistics - e.g. firstBlockMean(<600).
        -->
        <param name="NotificationThresholds" value="firstBlockMax(0-800),secondBlockMax(&lt;1500)"/>
        <!--
          You can also specify an optional MBeanName param, which overrides
          the default MBean name of net.jperftype=StatisticsExposingMBean,name=JPerf
        -->
    </appender>

    <!-- Loggers -->
    <!--
      The JPerf logger. Note that net.jperfTimingLogger is the value of the
      net.jperfStopWatch.DEFAULT_LOGGER_NAME constant. Also, note that
      additivity is set to false, which is usually what is desired - this means
      that timing statements will only be sent to this logger and NOT to
      upstream loggers.
    -->
    <logger name="net.jperf.TimingLogger" additivity="false">
        <level value="INFO"/>
        <appender-ref ref="CoalescingStatistics"/>
    </logger>

    <!--
      The root logger sends all log statements EXCEPT those sent to the jperf
      logger to System.out.
    -->
    <root>
        <level value="INFO"/>
        <appender-ref ref="console"/>
    </root>
</log4j:configuration>

java -Dcom.sun.management.jmxremote -cp .:./jperf-1.0.3.jar:./log4j-1.2.14.jar JPerfAppenderExample

import net.jperf.aop.*;

public class ProfiledExample {
    public static void main (String[] args) throws Exception {
        // run all of the examples
        for (int i = 0; i < 50; i++) {
            simpleExample();
            simpleExampleWithExplicitTag();
            dynamicTagExample("iIs" + (i % 2 == 0 ? "Even" : "Odd"));
            dynamicMessageExample(i % 2 == 0 ? 1000L : 2000L);
            if (i % 2 == 0) {
                logFailuresSeparatelyExample(false);
            } else {
                try {
                    logFailuresSeparatelyExample(true);
                } catch (Exception e) { /* expected */ }
            }
            nonDefaultLoggerNameExample();

            System.out.println("Ran loop " + i);
        }
    }

    /**
     * When the Profiled annotation is used without any parameters, the simple
     * name of the method is used as the tag for any logged timing statements
     */
    @Profiled
    public static void simpleExample() throws InterruptedException {
        Thread.sleep((long) (Math.random() * 1000L));
    }

    /**
     * Here we set the tag name to an explicit value.
     */
    @Profiled(tag = "simpleBlock")
    public static void simpleExampleWithExplicitTag() throws InterruptedException {
        Thread.sleep((long) (Math.random() * 1000L));
    }

    /**
     * One very useful feature of the Profiled annotation is the ability to
     * dynamically set the tag name based on the value of a method parameter.
     * You can make use of Jakarta Commons Java Expression Language (JEXL) in
     * curly braces in the tag name. The first parameter is assigned the variable
     * name $0, the second $1, etc. For example, if I had a method that took as
     * the first parameter an object with a bean accessor method "getFoo()", I
     * could write a tag as "myTag_{$0.foo}".
     *
     * In addition to method parameters, you can also access the following variables
     * in JEXL expressions:
     *
     * $this - the object whose method is being called.
     * $return - the return value from the method (this will be null if the method
     *           has a void return type or if the method throws an exception).
     * class java.lang.Object - the Class instance of the class owning the method being called.
     * $methodName - the name of the method being called.
     * $exception - if the method completes by throwing an exception, the $exception
     *              variable can be used to access the exception (this will be null
     *              if the method completes normlly).
     *
     */
    @Profiled(tag = "dynamicTag_{$0}")
    public static void dynamicTagExample(String tagName) throws InterruptedException {
        Thread.sleep((long) (Math.random() * 1000L));
    }

    /**
     * You can also specify a message to be logged in the Profiled annotation.
     */
    @Profiled(tag = "messageExample", message = "Requested sleep time was {$0 / 1000} seconds")
    public static void dynamicMessageExample(long requestedSleepTimeInMS) throws InterruptedException {
        Thread.sleep((long) (Math.random() * requestedSleepTimeInMS));
    }

    /**
     * Often times you want to log failures (where a method completes by throwing an exception)
     * separately from when a method completes normally. If you set the logFailuresSeparately
     * parameter to true, then the tag given to cases when the method completes normally will
     * be yourSpecifiedTagName.success, and when an exception is thrown the tag name will be
     * yourSpecifiedTagName.failure. This allows you to calculate separate performance statistics
     * for success and failure cases.
     */
    @Profiled(tag = "failuresSeparatelyExample", logFailuresSeparately = true)
    public static void logFailuresSeparatelyExample(boolean shouldFail) throws Exception {
        Thread.sleep((long) (Math.random() * 1000L));
        if (shouldFail) {
            throw new Exception("Method threw exception");
        }
    }

    /**
     * By default timing statements are logged to the logger named
     * StopWatch.DEFAULT_LOGGER_NAME (i.e. net.jperf.TimingLogger),
     * but this can be overridden.
     */
    @Profiled(tag = "loggerExample", logger = "net.jperf.MyCustomLoggerName")
    public static void nonDefaultLoggerNameExample() throws InterruptedException {
        Thread.sleep((long) (Math.random() * 1000L));
    }
}

import java.math.BigInteger;
import net.jperf.aop.Profiled;

public class PrimeGenerator {

    //keeps track of the prime we're going to return
    private BigInteger currentPrime = new BigInteger("0");

    public void setCurrentPrime(BigInteger currentPrime) {
        this.currentPrime = currentPrime;
    }

    @Profiled
    public BigInteger nextPrime() {
        currentPrime = currentPrime.nextProbablePrime();
        return currentPrime;
    }
}

<?xml version="1.0" encoding="UTF-8"?>

<!-- Note how the aop namespace is defined in the top-level beans element -->
<beans xmlns="http://www.springframework.org/schema/beans"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xmlns:aop="http://www.springframework.org/schema/aop"
       xsi:schemaLocation="http://www.springframework.org/schema/beans
                           http://www.springframework.org/schema/beans/spring-beans-2.0.xsd
                           http://www.springframework.org/schema/aop
                           http://www.springframework.org/schema/aop/spring-aop-2.0.xsd">

    <!--
      Including this aspectj-autoproxy element will cause spring to automatically
      create proxies around any beans defined in this file that match the pointcuts
      of any aspects defined in this file.
    -->
    <aop:aspectj-autoproxy/>

    <!--
      Declare the TimingAspect that we want to weave into the other beans
      defined in this config file.
    -->
    <bean id="timingAspect" class="net.jperf.log4j.aop.TimingAspect"/>

    <!--
      Because we included the aspectj-autoproxy element, Spring will automatically
      create a proxy for this bean that runs the TimingAspect around any public
      @Profiled methods on this bean.
    -->
    <bean id="primeGenerator" class="PrimeGenerator">
        <property name="currentPrime"
                  value="12345678910111213141516171819202122232425262728293031323334353637383940"/>
    </bean>
</beans>

import org.springframework.context.ApplicationContext;
import org.springframework.context.support.FileSystemXmlApplicationContext;

public class SpringProfiledExample {
    public static void main(String[] args) throws Exception {
        //initialize Spring
        ApplicationContext applicationContext = new FileSystemXmlApplicationContext("spring.xml");

        //Spring will actually return a CGLIB-generated proxy here that injects
        //the TimingAspects into the PrimeGenerator class.
        PrimeGenerator primeGenerator = (PrimeGenerator) applicationContext.getBean("primeGenerator");

        for (int i = 0; i < 500; i++) {
            System.out.println("nextPrime() returned " + primeGenerator.nextPrime());
        }
    }
}

Performance Statistics   18:46:50 - 18:47:00
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
nextPrime                                               31.3          24          73         6.9         277

Performance Statistics   18:47:00 - 18:47:10
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
nextPrime                                               31.0          24          78         7.2         223

@Stateless
public class HelloWorldBean implements HelloWorld {

    @Interceptors(net.jperf.log4j.aop.EjbTimingAspect.class)
    public void sayHello() {
        System.out.println("Hello!");
    }
}