JQuantify Tutorial
Contents
Introduction
Lesson
1: EventCounter
Lesson 2: SessionCounter
Lesson 3: Threadsafe, low overhead
Lesson
4: MetricRepository
Lesson 5:
MetricsServlet
Lesson 6: VMUsage
JQuantify provides Java developers a simple and effective way to instrument their programs and systems. This tutorial introduces a Java programmer to the package and its most interesting classes. While it does not cover every public method on every class, it does give enough details to begin to use the classes in a real program. (Consult the javadoc-generated documentation for the full API specification.) This tutorial also discusses various topics that will help readers understand what benefits the package might bring to their programs and some ways to achieve those benefits.
The tutorial is organized into a series of lessons. Each lesson includes a working program and can probably be completed in no more than 10 - 15 minutes. Please read the lessons in order, even if the examples are not studied carefully, since some important topics are introduced along the way will be helpful later.
The source and class files for the examples from this tutorial are included in the download. You should need nothing more than a machine with JDK1.2 or later to complete the tutorial. (Lesson 5 uses servlets, which requires Java classes that may not be present in your Java installation. Therefore it's source is shown in this tutorial but not placed in the download with the other examples.)
There are many events in programs worth counting. By event, we mean any type of occurrence noted by your program at specific points in time. Java, like most programming languages, provides for maintaining a running total of occurrences of some event using primitive types such as int and operators like ++. In order to provide a simple example, conside the program below that counts lines from an input stream. It reports the running total each time a line begins with "r", and exists when a line beings with "x".
import java.io.*;
public
class Example1 {
public static void
main(String args[]) {
int counter;
System.out.println(
"Example 1a:
counter" +
"\nEnter r
(report), or x (exit), or anything else just to count");
BufferedReader input =
new BufferedReader(new InputStreamReader(System.in));
while
(true) {
try {
String response =
input.readLine();
counter++;
if
(response.startsWith("r")) {
System.out.println("Counter:
" + counter);
} else if
(response.startsWith("x")) {
break;
}
} catch (IOException
e) {
System.out.println("Caught
" + e);
break;
}
}
}
}
Example 1a
An instance of an EventCounter goes beyond that by providing insight into the frequency of the occurrences
over the entire observation period,
in the recent past, and
at the peak occurrence rate.
You can count with an EventCounter much the same way you count with an int. Instead of ++ on an int, you use the add() method on a counter. When you display the counter with System.out.println(), instead of seeing just the total number of occurrences, you see a formatted summary containing the total as well as frequencies.
Example1 below is a modifcation of Example 1a to use EventCounter;
changes are shown in red.
import
com.berryworks.jquantify.*;
import
java.io.*;
public
class Example1 {
public static void
main(String args[]) {
EventCounter counter =
new EventCounter("HittingEnter");
System.out.println(
"Example 1: "
+ counter.getLabel()
+
"\nEnter r
(report), or x (exit), or anything else just to count");
BufferedReader input =
new BufferedReader(new InputStreamReader(System.in));
while
(true) {
try {
String response =
input.readLine();
counter.add();
if
(response.startsWith("r")) {
System.out.println(counter);
} else if
(response.startsWith("x")) {
break;
}
} catch (IOException
e) {
System.out.println("Caught
" + e);
break;
}
}
}
}
Example 1
To execute this program from a directory where JQuantify.jar is located, simply enter the command
java -cp JQuantify.jar Example1
After launching the program, try hitting Enter a few times and then enter a line beginning with "r" to see a summary of the counter. You should see something like this:
Summary of
HittingEnter
Fri
May 18 16:24:44 GMT+00:00 2003
Age: 6.67 seconds
Count: 8
Frequency (events/second)
Over
life of counter: 1.1972463
Current: 1.7835909
Peak:
2.0 at Fri May 18 16:24:40 GMT+00:00 2003
Interpreting the results shown above, we see that 6.67 seconds had elapsed from the time the counter was constructed until the summary was taken. At that point, Enter had been hit 8 times. That comes to a little over 1.19 events per second as shown.
Intervals
EventCounter internally treats time as a series of fixed-length intervals. The default interval time is 1 second. This default value is suitable for most purposes, but a different number of seconds for each interval can be specified with a second argument to the EventCounter constructor.
When the summary was generated, the current event rate was just over 1.78 events/second. This is computed from the most recent full interval plus the current partially completed interval. Therefore, depending upon exactly when the Enter for the "r" line is hit, the current frequency is reported over the last 1 to 2 seconds.
Over the life of this counter, the interval with the most events
had an event rate of 2.0events/second. This is shown as the peak
frequency.
The events observed by EventCounter in the previous lesson occurred at specific points in time as far as the counter was concerned. A perhaps more common need for program instrumentation is to track events that have measurable duration, that is, events that have a distinct start point and end point. SessionCounter is a subclass of EventCounter that is useful in measuring such events, known as sessions.
SessionCounter can be used to observe sessions that span minutes or hours, such as user login/logout sessions to a commercial service, or session as brief as a single method call in a Java program. A system clock with one millisecond granularity is used, so sessions with duration of less than a millisecond appear to take no time whatsoever.
Example2, shown below, is adapted from Example1 to exercise a
SessionCounter instead of an EventCounter. Each line that begins with
">" is treated as the start of a session; a line
beginning with "<" marks the end of a session. Note that
instead of using the add() method on the counter, start() and stop()
are used to note the distinct beginning and end of a session.
import
com.berryworks.jquantify.*;
import
java.io.*;
public
class Example2 {
public static void
main(String args[]) {
SessionCounter counter
= new SessionCounter("Sessions");
System.out.println(
"Metrics Example
2: " + counter.getLabel() +
"\nEnter >
(begin a session), < (end a session), r (report), or x (exit)");
BufferedReader input =
new BufferedReader(new InputStreamReader(System.in));
while
(true) {
try {
String response =
input.readLine();
if
(response.startsWith(">")) {
counter.start();
} else if
(response.startsWith("<")) {
counter.stop();
} else if
(response.startsWith("r")) {
System.out.println(counter);
} else if
(response.startsWith("x")) {
break;
}
} catch (IOException
e) {
System.out.println("Caught
" + e);
break;
}
}
}
}
Example 2
To execute this program, enter the command
java -cp JQuantify.jar Example2
You will want to experiment and consider the results produced. The results shown below were from entering > < > > > < < > > > < > <, each on a separate line with a slight pause between lines.
Summary
of Sessions
Fri May 18 18:12:52
GMT+00:00 2003
Age: 60.059 seconds
Count:
8
Frequency
(events/second)
Over life of counter:
0.13317353
Current: 0.0
Peak:
1.0 at Fri May 18 18:11:55 GMT+00:00 2003
Concurrency
Current:
3
Current peak: 4
Lifetime
peak: 4 at Fri May 18 18:12:12 GMT+00:00 2003
Session
duration (milliseconds)
Aggregate: 14440
Mean:
2888.0
Max: 1406 at Fri May
18 18:11:57 GMT+00:00 2003
Recent: 1406
The first portion of the summary is familiar. Since SessionCounter is a subclass of EventCounter, frequency counting is inherited and describes the frequency of sessions starting. The 8 corresponds to the eight >'s.
The next portion of the summary deals with session concurrency. For the input given, three sessions were started but not stopped at the time the summary was generated. Therefore, "current" concurrency is reported as 3. During the current (partially complete) interval, the peak concurrency was as high as 4. That is also the peak observed over the life of the metric.
The final portion of the summary deals with the duration of the five completed sessions. The total number of milliseconds spent in all the sessions, in aggregate, is 14440, or 14.4 seconds. That yields an average (mean) of 2888 milliseconds.
The maximum and recent session times must be used with care in
situations where sessions are often running concurrently, as in this
example. The recent session time of 1406 was observed on a session
that started and stopped with no other sessions going on. In this
case, that was the very first > < pair; all of the others had a
concurrency level greater than 1. In order to maintain extremely low
overhead as discussed in the next lesson, SessionCounter does not
match specific stop()s with specific start()s and therefore is not
able to unambiguously compute individual session times except when
there is only one session. A recent session duration, then, is merely
the duration of the most recent session that started and stopped
alone. The maximum duration reported is the maximum of the recent
observations. When the sessions under observation naturally occur one
at a time, or overlap only occasionally, the recent and maximum
durations reported are meaningful. Under other conditions, these
should be treated only as lower bounds.
Lesson 3: Threadsafe, low overhead
The metrics package is designed for permanently instrumenting a Java system, not merely as debugging or performance remediation techniques. A system designer can identify various types of events and sessions that, if observed with low-impact techniques, can provide a wealth of information to help
study usage patterns as input to the design of future versions of the system,
validate design assumptions,
infer system capacity limits and bottlenecks, and
compare before and after behavior of the system as the environment in which it operates undergoes change.
In order to be used to instrument Java classes in production,
EventCounter, SessionCounters, and other subclasses derived from the
abstract superclass Metric must be
threadsafe - give useful results when a given instance is accessed from concurrently executing threads, and
very low in overhead - consume truly negligable quantities of CPU cycles and memory.
The example in this lesson illustrates the use of shared
SessionCounters from concurrently running threads and estimates the
CPU overhead of executing a start/stop pair on a given machine
configuration. This example is a bit more complex than the previous
ones, a necessity in order to setup and monitor multiple threads. The
class's main takes command line parameters, supplies default values
as needed, and passes them as arguments to a run() method on a newly
constructed instance of Example3. The parameters are as follows.
Iterations - number of iterations by each thread over a measured section of code
Threads - number of concurrent threads to be used
Sleep - number of milliseconds to sleep within the measured code section
Out - name of a file to which the output is written
Shared access from multiple threads
The measured code section is nothing more than sleeping the proper number of milliseconds. A SessionCounter labeled "Example 3 Inner Counter" is wrapped around that section of code. (By "wrapped around" we mean a start() at the beginning of the section and a stop() at the end.) Each thread shares access to the same counter instance, providing for a degree of concurrency in proportion to the number of threads.
Estimating overhead
A second SessionCounter labeled "Example 3 Outer Counter"
is wrapped around the inner one in order to count the measured
section plus the overhead introduced by the inner counter. Therefore,
the difference between the mean session times of the outer counter
and the inner counter provides an estimate of the overhead of a given
start/stop pair.
import
com.berryworks.jquantify.*;
import
java.io.*;
public class Example3 {
public
void run(int iterations, int threads, int sleep, PrintStream out) {
System.out.println("Examle
3: MetricRepository, mutliple threads, overhead");
System.out.println("Package
version: " + Version.getVersion());
System.out.println("Critical
section: " + sleep + " millisecond sleep");
System.out.println(
"Running " +
threads + " concurrent threads, each doing " +
iterations + "
iterations");
System.out.println();
//
Construct each thread and tell them to get going.
for
(int i = 0; i < threads; i++) {
DemoThread t = new
DemoThread(iterations, sleep);
(new
Thread(t)).start();
}
//
Wake up every second and peak at their progress.
SessionCounter c1 =
SessionCounter.getSessionCounter("Example 3 Inner Counter");
SessionCounter c2 =
SessionCounter.getSessionCounter("Example 3 Outer Counter");
while
(true) {
try {
Thread.sleep(1000);
} catch (Exception e)
{}
out.println(c1);
out.println(c2);
if
(c1.getCumulativeEvents() >= threads * iterations) {
break;
}
}
float
overhead = c2.getSessionTimeMean() - c1.getSessionTimeMean();
System.out.println(
"\n\nOverhead per
start/stop pair: " + overhead + " milliseconds\n");
}
class
DemoThread implements Runnable {
private int
iterations, sleep;
private SessionCounter
innerCounter, outerCounter;
/**
*Constructor for the
DemoThread object
*
*
@param iterations Description of the Parameter
*
@param sleep Description of
the Parameter
*/
public
DemoThread(int iterations, int sleep) {
this.iterations =
iterations;
this.sleep = sleep;
innerCounter =
SessionCounter.getSessionCounter("Example 3 Inner Counter");
outerCounter =
SessionCounter.getSessionCounter("Example 3 Outer Counter");
}
/**
*
Main processing method for the DemoThread object
*/
public
void run() {
for (int i = 0; i <
iterations; i++) {
// Sleep a small
random number of milliseconds so that
// the threads running
in parallel enter and exit their
// measured sections
in a staggered manner.
try {
Thread.sleep((long)
(Math.random() * 10));
} catch (Exception e)
{}
outerCounter.start();
innerCounter.start();
try {
Thread.sleep(sleep);
} catch (Exception e)
{}
innerCounter.stop();
outerCounter.stop();
}
}
}
/**
*
Run the program
*
*
@param args iterations threads sleep outputfile
*/
public
static void main(String args[]) {
// Number of
iterations
int n1 = 10000;
if
(args.length >= 1) {
try {
n1 =
Integer.parseInt(args[0]);
} catch
(NumberFormatException e) {}
}
//
Number of threads
int n2 = 10;
if
(args.length >= 2) {
try {
n2 =
Integer.parseInt(args[1]);
} catch
(NumberFormatException e) {}
}
//
Number of milliseconds to sleep within inner loop
int
n3 = 1;
if (args.length >=
3) {
try {
n3 =
Integer.parseInt(args[2]);
} catch
(NumberFormatException e) {}
}
//
Name of output file
PrintStream
outputStream = System.out;
if (args.length >=
4) {
try {
outputStream = new
PrintStream(new FileOutputStream(args[3]));
} catch
(FileNotFoundException e) {
System.out.println("Cannot
open output file: " + args[3] + e);
}
}
(new
Example3()).run(n1, n2, n3, outputStream);
}
}
Example 3
You will notice that Example 3 does not use new SessionCounter(label) to construct its counters. Instead, it uses SessionCounter.get(label), a technique presented in the next lesson.
You can execute Example3 just as you did the previous examples. The last portion of output produced is shown below.
Summary
of Example 3 Inner Counter
Tue May 22 17:14:09
GMT+00:00 2003
Age: 39.202 seconds
Count:
10000
Frequency
(events/second)
Over life of counter:
255.08904
Current: 123.06994
Peak:
270.0 at Tue May 22 17:13:45 GMT+00:00 2003
Concurrency
Current:
0
Current peak: 5
Lifetime
peak: 10 at Tue May 22 17:13:36 GMT+00:00 2003
Session
duration (milliseconds)
Aggregate: 199830
Mean:
19.983
Max: 20 at Tue May 22
17:14:09 GMT+00:00 2003
Recent: 20
Summary
of Example 3 Outer Counter
Tue May 22 17:14:09
GMT+00:00 2003
Age: 39.185 seconds
Count:
10000
Frequency
(events/second)
Over life of counter:
255.19969
Current: 123.11213
Peak:
270.0 at Tue May 22 17:13:36 GMT+00:00 2003
Concurrency
Current:
0
Current peak: 5
Lifetime
peak: 10 at Tue May 22 17:13:36 GMT+00:00 2003
Session
duration (milliseconds)
Aggregate: 199954
Mean:
19.9954
Max: 20 at Tue May 22
17:14:09 GMT+00:00 2003
Recent: 20
Overhead
per start/stop pair: 0.012399673 milliseconds
In instrumenting a Java system of any size, it is often appropriate to decouple the portions of the system that use metrics to count events as they are processed from the portions of the system that view those metrics in some manner. If the Model-View-Controller (MVC) pattern is used, for example, it is natural for EventCounters and SessionCounters to be updated in the model and controller classes while the viewer classes will likely need access to those same metrics for presentation purposes. The MetricRepository class provides a simple way to achieve this decoupling.
Simply put, MetricRepository is a singleton object that contains a collection of metrics hashed by their label. Metrics in the repository, uniquely labelled, are globally accessible throughout the VM by means of a static get(label) method. Similarly, the static put(Metric) method allows a metric object to be placed into the repository.
Example4 below illustrates two slightly different ways to use MetricRepository. Note that a SessionCounter labeled "Pre-Created" is explicitly constructed in one part of the program, placed into the repository with MetricRepository.put() and later referenced from another part of the program with SessionCounter.get(). Another SessionCounter, this one labeled "Created-on-demand", is not constructed at all by the application; it is created automatically when the get() method is invoked. There is a similar get() defined for EventCounter, as you would expect.
import com.berryworks.jquantify.*;
public class Example4 {
public
void run() {
SessionCounter
sc1,sc2;
sc1 =
SessionCounter.getSessionCounter("Pre-Created");
sc2
= SessionCounter.getSessionCounter("Created-on-demand");
System.out.println(sc1.toXML());
System.out.println(sc2.toXML());
}
public static void
main(String args[]) {
SessionCounter sc =
new SessionCounter("Pre-Created");
sc.start();
MetricRepository.put(sc);
sc.stop();
(new
Example4()).run();
}
}
Example 4
Metrics exported as XML documents
You may have noticed another method not seen before: toXML(). Each
subclass of Metric has an appropriate toString() that allows a metric
to be used in a String context such as the println() calls in earlier
examples. Each subclass also provides a toXML() method that is
equivalent to the toString() except that the results are expressed in
XML syntax instead of a text report. The XML output produced by
Example4 is shown below.
<?xml
version="1.0" encoding="utf-8"?>
<metric
class="com.berryworks.jquantify.SessionCounter"
version="3.3.0">
<label>Pre-Created</label>
<time>Tue
May 22 17:05:04 GMT+00:00 2003</time>
<age
units="seconds">0.435</age>
<count>1</count>
<frequency
units="events/second">
<life>2.2421525</life>
<curr>0.691085</curr>
<peak>0.0<time>Tue
May 22 17:05:03 GMT+00:00 2003</time></peak>
</frequency>
<concurrency
units="sessions started">
<curr>0</curr>
<peak>1<time>Tue
May 22 17:05:03 GMT+00:00 2003</time></peak>
</concurrency>
<runtime
units="milliseconds">
421
<mean>421.0</mean>
<max>421<time>Tue
May 22 17:05:04 GMT+00:00 2003</time></max>
<recent>421</recent>
</runtime>
</metric>
<?xml
version="1.0" encoding="utf-8"?>
<metric
class="com.berryworks.jquantify.SessionCounter"
version="3.3.0">
<label>Created-on-demand</label>
<time>Tue
May 22 17:05:04 GMT+00:00 2003</time>
<age
units="seconds">0.471</age>
<count>0</count>
<frequency
units="events/second">
<life>0.0</life>
<curr>0.0</curr>
<peak>0.0<time>Tue
May 22 17:05:04 GMT+00:00 2003</time></peak>
</frequency>
<concurrency
units="sessions started">
<curr>0</curr>
<peak>0<time>Tue
May 22 17:05:04 GMT+00:00 2003</time></peak>
</concurrency>
<runtime
units="milliseconds">
0
<mean>0.0</mean>
<max>0</max>
<recent>0</recent>
</runtime>
</metric>
Metrics exported in Comma Separated Values (.csv) format
In addition to the text report produced by toString() and the XML document produced by toXML(), a metric's content can be exported in .csv format suitable for reading by spreadsheet programs. The toCSV() method performs this function.
If the instrumented Java system operates in a servlet container, it is very simple to provide for remote access to your system's metrics in the MetricRepository. Simply provide a servlet, or Java Servlet Page (JSP), that responds to an http request by retrieving a metric from the repository and invoking the metric's toString(), toXML(), or toCSV() as desired.
The example servlet below is usable as-is for this purpose, although it needs a servlet container in which to run. Notice that it this servlet is itself instrumented using a SessionCounter to track hits and time spent by this servlet.
You may, of course, develop custom servlets integrated with your
system's own servlets. Note that an instrumented EJB system with a
Servlet front-end can use this same technique by means of a trivial
EJB SessionBean that exports a requested metric from the
MetricRepository in the EJB container's VM. The Metric class is
Serializable for the reason.
import
java.io.*;
import
javax.servlet.*;
import
javax.servlet.http.*;
import com.berryworks.jquantify.*;
public class MetricsServlet extends HttpServlet {
public
void doGet (HttpServletRequest req, HttpServletResponse res)
throws
ServletException, IOException
{
/**
*
Access MetricsServerCounter, a metric
* that instruments
this MetricsServlet itself.
**/
SessionCounter
myMetric = SessionCounter.getSessionCounter"MetricsServlet");
myMetric.start();
res.setContentType("text/html");
String
metricLabel = req.getParameter("Metric");
if
(metricLabel==null) metricLabel = "(null)";
ServletOutputStream out = res.getOutputStream();
Metric
metric = MetricRepository.get(metricLabel);
if
(metric==null) {
out.println(" not
in repository");
} else {
String reset =
req.getParameter("Reset");
if (reset!=null)
metric.reset();
out.println(metric.toXML());
}
myMetric.stop();
}
}
Example 5
In addition to the EventCounter and SessionCounter subclasses of Metric that are the primary tools for instrumenting Java programs, there is another subclasses that may be useful. The VMUsage class provides information about the threads and memory usage within the VM. It is not necessary to call add() or start()/stop() on a metric of this type; each time toString(), toXML(), or toCSV() is called, the object takes a fresh sample of the values. This is illustrated in Example6 below.
import com.berryworks.jquantify.*;
public
class Example6 {
public static void
main(String args[]) {
Metric vm =
MetricRepository.get("VMUsage");
System.out.println(vm.toXML());
}
}
Example 6
There is another feature of MetricRepository worth mentioning at this point. When the MetricRepository class is loaded by the classloader, it constructs a VMUsage labeled "VMUsage" and places it in the repository. Therefore, the age of this metric can often be used as an indicator of when the VM was started. Sample output produced by Example6 follows.
<?xml
version="1.0" encoding="utf-8"?>
<metric
class="com.berryworks.jquantify.VMUsage" version="3.3.0">
<label>VMUsage</label>
<time>Tue
May 22 17:46:15 GMT+00:00 2003</time>
<age
units="seconds">0.449</age>
<samples>2</samples>
<threads>
<current>1</current>
<min>1</min>
<max>1</max>
<mean>1.0</mean>
</threads>
<memory>
<total>
<current
units="bytes">8388608</current>
<min>8388608</min>
<max>8388608</max>
<mean
units="Mbytes">8.388608</mean>
</total>
<free>
<current
units="bytes">7889776</current>
<min>7889776</min>
<max>7904352</max>
<mean
units="Mbytes">7.897064</mean>
</free>
</memory>
</metric>