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.