Hammurapi Group
Java tools and libraries
Products
Hammurapi
Hammurapi rules
jIncarnate

Supporting libraries
Common library
Enterprise extensions
Mesopotamia

Contact us
Discussion board
Newsletter
The metrics framework, which is part of the Common library, is described in Metrics framework. This document describes remote metrics collection over TCP/IP and how to instrument existing classes for metrics collection using Aspectwerkz.

Figure 1. Solution architecture

In this article we will collect greet() method execution time metrics for the following class

package biz.hammurapi.test;

public class HelloWorld {
   
    public String greet() {
        try {
            Thread.sleep((long) (Math.random()*50+5));
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        return "Hello world!";
    }

    /**
     * @param args
     */
    public static void main(String[] args) {       
        HelloWorld hw = new HelloWorld();   
        for (int i=0; i<500; ++i) {
            hw.greet();
        }
    }

}


In this class the greet() method take random number of milliseconds between 5 and 55. The method is invoked 500 times.

Explicit metrics collection

First of all you shall download Enterprise extensions here and unzip it to a local directory. Set up environment variable HGEE_HOME pointing to this directory. This article assumes that you use Windows and environment variables are surrounded by % signs, e.g. %HGEE_HOME%

Start server

Execute

start java -cp %HGEE_HOME%\lib\hgee.jar;%HGEE_HOME%\lib\hgcommons.jar biz.hammurapi.metrics.SocketSliceConsumerServer

from the command line to start metrics collection server. The server listens on port 9814 by default. You can provide another port number as a command line parameter.

Modify source

Now we shall add metrics collecting statements. For this we'll make a copy of the HelloWorld class and name it MeasuringHelloWorld

package biz.hammurapi.test;

import biz.hammurapi.metrics.MeasurementCategory;
import biz.hammurapi.metrics.MeasurementCategoryFactory;

public class MeasuringHelloWorld {
    
    static MeasurementCategory mc = MeasurementCategoryFactory.getCategory(MeasuringHelloWorld.class);    
    
    public String greet() {
        long start = System.currentTimeMillis();
        try {
            Thread.sleep((long) (Math.random()*50+5));
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        long now = System.currentTimeMillis();
        mc.addMeasurement("greeting", now-start, now);
        return "Hello world!";
    }

    /**
     * @param args
     */
    public static void main(String[] args) {        
        MeasuringHelloWorld hw = new MeasuringHelloWorld();    
        for (int i=0; i<500; ++i) {
            hw.greet();
        }
    }

}

Changes are highlighted in bold. Compile this class

javac -cp %HGEE_HOME%\lib\hgee.jar;%HGEE_HOME%\lib\hgcommons.jar;%HGEE_HOME%\lib\xalan.jar HelloWorld.java MeasuringHelloWorld.java

and move the .class file to classes\biz\hammurapi\test directory. Also create pv-metrics-config.xml in classes directory to configure the metrics framework.

<metrics-config type="java.util.ArrayList">
    <element type="biz.hammurapi.metrics.SlicingMeasurementCategoryFactory">
        <tick>1000</tick>
        <max-queue>1000</max-queue>
        <category>biz.hammurapi</category>
        <slice-consumer type="biz.hammurapi.metrics.SocketSliceConsumer"/>
    </element>
</metrics-config>

Run the MeasuringHellowWorld

java -cp classes;%HGEE_HOME%\lib\hgcommons.jar;%HGEE_HOME%\lib\xalan.jar;%HGEE_HOME%\lib\hgee.jar biz.hammurapi.test.MeasuringHelloWorld
You will notice the following output in the server window
SLICE [/127.0.0.1] biz.hammurapi.test.MeasuringHelloWorld: Name=greeting; Total=1047.0; Avg=29.914285714285715; Min=0.0; Max=47.0; Deviation=12.811923185398824; From=1186081792293 (Thu Aug 02 15:09:52 EDT 2007); To=1186081793309 (Thu Aug 02 15:09:53 EDT 2007); Measurements=35
SLICE [/127.0.0.1] biz.hammurapi.test.MeasuringHelloWorld: Name=greeting; Total=47.0; Avg=15.666666666666666; Min=15.0; Max=16.0; Deviation=0.27777777777777796; From=1186081806951 (Thu Aug 02 15:10:06 EDT 2007); To=1186081806983 (Thu Aug 02 15:10:06 EDT 2007); Measurements=3
SLICE [/127.0.0.1] biz.hammurapi.test.MeasuringHelloWorld: Name=greeting; Total=1047.0; Avg=29.914285714285715; Min=0.0; Max=63.0; Deviation=11.713840703028335; From=1186081793324 (Thu Aug 02 15:09:53 EDT 2007); To=1186081794356 (Thu Aug 02 15:09:54 EDT 2007); Measurements=35
SLICE [/127.0.0.1] biz.hammurapi.test.MeasuringHelloWorld: Name=greeting; Total=1031.0; Avg=27.864864864864863; Min=0.0; Max=62.0; Deviation=10.819171011418836; From=1186081794371 (Thu Aug 02 15:09:54 EDT 2007); To=1186081795387 (Thu Aug 02 15:09:55 EDT 2007); Measurements=37
SLICE [/127.0.0.1] biz.hammurapi.test.MeasuringHelloWorld: Name=greeting; Total=1016.0; Avg=27.45945945945946; Min=0.0; Max=62.0; Deviation=10.725665688682799; From=1186081795403 (Thu Aug 02 15:09:55 EDT 2007); To=1186081796403 (Thu Aug 02 15:09:56 EDT 2007); Measurements=37
SLICE [/127.0.0.1] biz.hammurapi.test.MeasuringHelloWorld: Name=greeting; Total=1016.0; Avg=28.22222222222222; Min=0.0; Max=63.0; Deviation=14.095217265866761; From=1186081796419 (Thu Aug 02 15:09:56 EDT 2007); To=1186081797419 (Thu Aug 02 15:09:57 EDT 2007); Measurements=36
SLICE [/127.0.0.1] biz.hammurapi.test.MeasuringHelloWorld: Name=greeting; Total=1078.0; Avg=33.6875; Min=0.0; Max=63.0; Deviation=12.490774286193691; From=1186081797466 (Thu Aug 02 15:09:57 EDT 2007); To=1186081798497 (Thu Aug 02 15:09:58 EDT 2007); Measurements=32
SLICE [/127.0.0.1] biz.hammurapi.test.MeasuringHelloWorld: Name=greeting; Total=1047.0; Avg=26.175; Min=0.0; Max=63.0; Deviation=14.950108522212052; From=1186081798544 (Thu Aug 02 15:09:58 EDT 2007); To=1186081799544 (Thu Aug 02 15:09:59 EDT 2007); Measurements=40
SLICE [/127.0.0.1] biz.hammurapi.test.MeasuringHelloWorld: Name=greeting; Total=1047.0; Avg=34.9; Min=0.0; Max=63.0; Deviation=10.571668245295884; From=1186081799591 (Thu Aug 02 15:09:59 EDT 2007); To=1186081800591 (Thu Aug 02 15:10:00 EDT 2007); Measurements=30
SLICE [/127.0.0.1] biz.hammurapi.test.MeasuringHelloWorld: Name=greeting; Total=1063.0; Avg=30.37142857142857; Min=15.0; Max=62.0; Deviation=11.876942871123326; From=1186081800638 (Thu Aug 02 15:10:00 EDT 2007); To=1186081801654 (Thu Aug 02 15:10:01 EDT 2007); Measurements=35
SLICE [/127.0.0.1] biz.hammurapi.test.MeasuringHelloWorld: Name=greeting; Total=1094.0; Avg=34.1875; Min=0.0; Max=63.0; Deviation=13.529622990124286; From=1186081801701 (Thu Aug 02 15:10:01 EDT 2007); To=1186081802748 (Thu Aug 02 15:10:02 EDT 2007); Measurements=32
SLICE [/127.0.0.1] biz.hammurapi.test.MeasuringHelloWorld: Name=greeting; Total=1078.0; Avg=27.641025641025642; Min=0.0; Max=62.0; Deviation=12.970056583059202; From=1186081802795 (Thu Aug 02 15:10:02 EDT 2007); To=1186081803826 (Thu Aug 02 15:10:03 EDT 2007); Measurements=39
SLICE [/127.0.0.1] biz.hammurapi.test.MeasuringHelloWorld: Name=greeting; Total=1031.0; Avg=30.323529411764707; Min=0.0; Max=63.0; Deviation=11.722080515857208; From=1186081803857 (Thu Aug 02 15:10:03 EDT 2007); To=1186081804857 (Thu Aug 02 15:10:04 EDT 2007); Measurements=34
SLICE [/127.0.0.1] biz.hammurapi.test.MeasuringHelloWorld: Name=greeting; Total=1032.0; Avg=30.352941176470587; Min=0.0; Max=63.0; Deviation=12.087250178204075; From=1186081804873 (Thu Aug 02 15:10:04 EDT 2007); To=1186081805889 (Thu Aug 02 15:10:05 EDT 2007); Measurements=34
SLICE [/127.0.0.1] biz.hammurapi.test.MeasuringHelloWorld: Name=greeting; Total=1047.0; Avg=25.536585365853657; Min=0.0; Max=63.0; Deviation=11.775209414995992; From=1186081805936 (Thu Aug 02 15:10:05 EDT 2007); To=1186081806936 (Thu Aug 02 15:10:06 EDT 2007); Measurements=41
You can run server on a different machine or use different port. In this case you shall add address and port elements to pv-metrics-config.xml as shown below

<metrics-config type="java.util.ArrayList">
    <element type="biz.hammurapi.metrics.SlicingMeasurementCategoryFactory">
        <tick>1000</tick>
        <max-queue>1000</max-queue>
        <category>biz.hammurapi</category>
        <slice-consumer type="biz.hammurapi.metrics.SocketSliceConsumer"/>
        <address>metricshost</address>
        <port>1234</port>
    </element>
</metrics-config>

Using aspects

With AOP we can instrument compiled code without having to modify sources. Enterprise extensions comes with an Aspectwerkz aspect  to collect method invocation time metrics. The aspect code is shown below

package biz.hammurapi.metrics;

import java.lang.reflect.Method;
import java.util.Stack;

import org.codehaus.aspectwerkz.joinpoint.MethodSignature;
import org.codehaus.aspectwerkz.joinpoint.StaticJoinPoint;

import biz.hammurapi.metrics.MeasurementCategory;
import biz.hammurapi.metrics.MeasurementCategoryFactory;

/**
 * Metrics collecting aspect.
 * @author Pavel
 */
public class MetricsAspect {
    private static MeasurementCategory mc = MeasurementCategoryFactory
            .getCategory(MetricsAspect.class);

    /**
     * Call stack
     */
    private ThreadLocal calls = new ThreadLocal() {

        protected Object initialValue() {
            return new Stack();
        }

    };

    /**
     * This method pushes method start time to a thread local stack.
     * @param joinPoint
     */
    public void before(StaticJoinPoint joinPoint) {
        ((Stack) calls.get()).push(new Long(System.currentTimeMillis()));
    }

    /**
     * This method pops method start time from the thread local stack and reports method duration measurement.
     * @param joinPoint
     */
    public void after(StaticJoinPoint joinPoint) {
        Method method = ((MethodSignature) joinPoint.getSignature()).getMethod();
        Stack tlStack = (Stack) calls.get();
        if (!tlStack.isEmpty()) {
            Long start = (Long) (tlStack).pop();
   
            if (start != null) {   
                long now = System.currentTimeMillis();   
                mc.addMeasurement(method.toString(), now - start.longValue(), now);   
            }
        }
    }

}

Download Aspectwerkz 2.0, unzip it to some directory on your disk and set ASPECTWERKZ_HOME environment variable. Then modify %ASPECTWERKZ_HOME%\bin\aspectwerkz.bat by adding Enterprise extensions jars to ASPECTWERKZ_LIB variable as shown below

ASPECTWERKZ_LIBS=%HGEE_HOME%\lib\hgee.jar;%HGEE_HOME%\lib\hgcommons.jar;%HGEE_HOME%\lib\xalan.jar;...other libraries...

Compile HelloWorld 

javac HelloWorld.java 
and move to classes\biz\hammurapi\test directory. You can run it and see that nothing happens in the server window.
java -cp classes;%HGEE_HOME%\lib\hgcommons.jar;%HGEE_HOME%\lib\xalan.jar;%HGEE_HOME%\lib\hgee.jar biz.hammurapi.test.HelloWorld
Now weave aspects into the code. We will use offline weaving. Below is the content of aop.xml
<aspectwerkz>
<system id="AspectWerkzExample">
<package name="biz.hammurapi.metrics">
<aspect class="MetricsAspect">
<pointcut name="greetMethod" expression="execution(* biz.hammurapi.test.HelloWorld.greet(..))"/>
<advice name="before" type="before" bind-to="greetMethod"/>
<advice name="after" type="after" bind-to="greetMethod"/>
</aspect>
</package>
</system>
</aspectwerkz>
Execute 
%ASPECTWERKZ_HOME%\bin\aspectwerkz -offline aop.xml classes
to weave. Then run HelloWorld again
run java -cp classes;%HGEE_HOME%\lib\hgcommons.jar;%HGEE_HOME%\lib\xalan.jar;%HGEE_HOME%\lib\hgee.jar;%ASPECTWERKZ_HOME%\lib\aspectwerkz-2.0.jar;%ASPECTWERKZ_HOME%\lib\aspectwerkz-core-2.0.jar -Daspectwerkz.definition.file=aop.xml biz.hammurapi.test.HelloWorld
You shall see output in the server window similar to the shown below
SLICE [/127.0.0.1] biz.hammurapi.metrics.MetricsAspect: Name=public java.lang.String biz.hammurapi.test.HelloWorld.greet(); Total=1047.0; Avg=26.175; Min=0.0; Max=63.0; Deviation=13.698627058899788; From=1186085179792 (Thu Aug 02 16:06:19 EDT 2007); To=1186085180792 (Thu Aug 02 16:06:20 EDT 2007); Measurements=40
SLICE [/127.0.0.1] biz.hammurapi.metrics.MetricsAspect: Name=public java.lang.String biz.hammurapi.test.HelloWorld.greet(); Total=890.0; Avg=29.666666666666668; Min=15.0; Max=47.0; Deviation=9.61922490283299; From=1186085193278 (Thu Aug 02 16:06:33 EDT 2007); To=1186085194137 (Thu Aug 02 16:06:34 EDT 2007); Measurements=30
SLICE [/127.0.0.1] biz.hammurapi.metrics.MetricsAspect: Name=public java.lang.String biz.hammurapi.test.HelloWorld.greet(); Total=1031.0; Avg=28.63888888888889; Min=0.0; Max=47.0; Deviation=9.798995809540052; From=1186085180823 (Thu Aug 02 16:06:20 EDT 2007); To=1186085181823 (Thu Aug 02 16:06:21 EDT 2007); Measurements=36
SLICE [/127.0.0.1] biz.hammurapi.metrics.MetricsAspect: Name=public java.lang.String biz.hammurapi.test.HelloWorld.greet(); Total=1016.0; Avg=27.45945945945946; Min=0.0; Max=62.0; Deviation=12.48807177579837; From=1186085181839 (Thu Aug 02 16:06:21 EDT 2007); To=1186085182839 (Thu Aug 02 16:06:22 EDT 2007); Measurements=37
SLICE [/127.0.0.1] biz.hammurapi.metrics.MetricsAspect: Name=public java.lang.String biz.hammurapi.test.HelloWorld.greet(); Total=1063.0; Avg=24.72093023255814; Min=0.0; Max=63.0; Deviation=11.786804624945713; From=1186085182886 (Thu Aug 02 16:06:22 EDT 2007); To=1186085183902 (Thu Aug 02 16:06:23 EDT 2007); Measurements=43
SLICE [/127.0.0.1] biz.hammurapi.metrics.MetricsAspect: Name=public java.lang.String biz.hammurapi.test.HelloWorld.greet(); Total=1015.0; Avg=32.74193548387097; Min=0.0; Max=63.0; Deviation=13.915825947065738; From=1186085183902 (Thu Aug 02 16:06:23 EDT 2007); To=1186085184917 (Thu Aug 02 16:06:24 EDT 2007); Measurements=31
SLICE [/127.0.0.1] biz.hammurapi.metrics.MetricsAspect: Name=public java.lang.String biz.hammurapi.test.HelloWorld.greet(); Total=1016.0; Avg=29.88235294117647; Min=0.0; Max=62.0; Deviation=12.329070489561614; From=1186085184933 (Thu Aug 02 16:06:24 EDT 2007); To=1186085185933 (Thu Aug 02 16:06:25 EDT 2007); Measurements=34
SLICE [/127.0.0.1] biz.hammurapi.metrics.MetricsAspect: Name=public java.lang.String biz.hammurapi.test.HelloWorld.greet(); Total=1063.0; Avg=27.256410256410255; Min=0.0; Max=63.0; Deviation=13.062004444278845; From=1186085185980 (Thu Aug 02 16:06:25 EDT 2007); To=1186085186996 (Thu Aug 02 16:06:26 EDT 2007); Measurements=39
SLICE [/127.0.0.1] biz.hammurapi.metrics.MetricsAspect: Name=public java.lang.String biz.hammurapi.test.HelloWorld.greet(); Total=1047.0; Avg=29.083333333333332; Min=0.0; Max=62.0; Deviation=12.058403983445594; From=1186085187011 (Thu Aug 02 16:06:27 EDT 2007); To=1186085188043 (Thu Aug 02 16:06:28 EDT 2007); Measurements=36
SLICE [/127.0.0.1] biz.hammurapi.metrics.MetricsAspect: Name=public java.lang.String biz.hammurapi.test.HelloWorld.greet(); Total=1016.0; Avg=30.78787878787879; Min=0.0; Max=47.0; Deviation=11.351229474056659; From=1186085188058 (Thu Aug 02 16:06:28 EDT 2007); To=1186085189059 (Thu Aug 02 16:06:29 EDT 2007); Measurements=33
SLICE [/127.0.0.1] biz.hammurapi.metrics.MetricsAspect: Name=public java.lang.String biz.hammurapi.test.HelloWorld.greet(); Total=1062.0; Avg=27.94736842105263; Min=0.0; Max=62.0; Deviation=11.777411822340008; From=1186085189105 (Thu Aug 02 16:06:29 EDT 2007); To=1186085190121 (Thu Aug 02 16:06:30 EDT 2007); Measurements=38
SLICE [/127.0.0.1] biz.hammurapi.metrics.MetricsAspect: Name=public java.lang.String biz.hammurapi.test.HelloWorld.greet(); Total=1016.0; Avg=29.02857142857143; Min=0.0; Max=47.0; Deviation=10.70145169408077; From=1186085190137 (Thu Aug 02 16:06:30 EDT 2007); To=1186085191137 (Thu Aug 02 16:06:31 EDT 2007); Measurements=35
SLICE [/127.0.0.1] biz.hammurapi.metrics.MetricsAspect: Name=public java.lang.String biz.hammurapi.test.HelloWorld.greet(); Total=1031.0; Avg=31.242424242424242; Min=0.0; Max=47.0; Deviation=9.283288288325235; From=1186085191168 (Thu Aug 02 16:06:31 EDT 2007); To=1186085192168 (Thu Aug 02 16:06:32 EDT 2007); Measurements=33
SLICE [/127.0.0.1] biz.hammurapi.metrics.MetricsAspect: Name=public java.lang.String biz.hammurapi.test.HelloWorld.greet(); Total=1079.0; Avg=30.82857142857143; Min=0.0; Max=63.0; Deviation=14.10470242182723; From=1186085192215 (Thu Aug 02 16:06:32 EDT 2007); To=1186085193247 (Thu Aug 02 16:06:33 EDT 2007); Measurements=35
You can see that category name is biz.hammurapi.metrics.MetricsAspect and slice name is the fully qualified name of the greet() method.

Overhead of instrumentation

On Dual Core Pentium 2.00 Ghz overhead of instumentation is 8 nanoseconds per invocation.

Subclassing the server

SocketSliceConsumerServer delegates metrics output to ConsoleSliceConsumer. You can subclass biz.hammurapi.metrics.SocketSliceConsumerServer and override its getDelegate() method to have metrics written to a database, XML file or to generate charts. Common library and  Enterprise extensions have a number of consumers which you can use out of the box. You can also write your own slice consumer.

Hammurapi Group