See: Description
| Interface | Description |
|---|---|
| DerivedComputation |
A metric that is
computed from something in your application, including stop watches.
|
| StopWatchFactory |
Allows you to provide your own instance of the StopWatch which subclasses
the StopWatch class.
|
| Class | Description |
|---|---|
| Logging |
This class exists as part of a move to
get away from a dependence on Log4j
|
| MemoryWatch |
Keeps an eye on memory utilization.
|
| NanoTime |
Provides a way to get and manipulate absolute time in nanoseconds.
|
| Statistic |
Implements the math for computing average, standard deviation, and
coefficient of variation.
|
| StopWatch |
Keeps track of a time interval and interval statistics for repeated starts and stops.
|
| StopWatchWithNesting | |
| Timing |
Methods to instrument code to track selected code paths.
|
A tool to help profile the execution-time characteristics of Java code. The classes use Java's nanosecond timing capability to get the best resolution possible. See the note below about nanosecond timing.
This package has functions in the following areas:
Java can report relative time in nanoseconds with the System.nanoTime() call.
The time is relative to the start of the machine and is useful for doing
relative timing such as those done by this package. However, there is no
guarantee that the time has nanosecond resolution. It depends
on the operating system and the hardware. Nevertheless it is generally better than
the millisecond time available from the System.currentTimeMillis() call.
You can use the method Timing.determineNanosecondGranularity() to determine
the resolution of the system. To get meaningful measurements the elapsed time of the code sections
that you measure should exceed this minimum resolution. If they exceed this but only by a little do
repeated measurements and average them to obtain a more reliable number.
Even if the measurements that you are making significantly exceed this minimum resolution Java timing's can vary by tens of milliseconds due to the interactions of the various threads at runtime (including the garbage collector).
public void simpleMethod() {
final StopWatch t1 = Timing.createStopWatch("a simple delay measurement");
t1.start();
delay();
t1.stop();
Timing.dumpTimings("Results of the simple test.");
}
private static void delay() {
try {
Thread.sleep(20);
}
catch (InterruptedException ignore) {}
}
Results of the simple test.
a simple delay measurement (org.mitre.javaTiming.TestSimpleTiming.simple1-15) = 21.700 ms. (1 iter.)
In the simple example there was only one line of output for the single StopWatch used. Note that the output identifies the label used when the StopWatch was created as well as the actual class, method, and line number of the code that created the StopWatch. When there are several StopWatches in various parts of complex code the latter helps you find your StopWatches should you forget where they were :) It also helps decipher the meanings of the timings if the labels that you use for the StopWatches are not as descriptive as they should be.
If the compiler options are set to suppress line number generation to the .class files then an internal sequence number will be generated instead of the line number.
public class ExampleBetterSimpleTiming {
private static final boolean ENABLE_TIMING = true;
private static StopWatch t1; //declaration of the StopWatch
public static void main(String[] args) {
for (int i = 0; i<10; i++){
if (ENABLE_TIMING){ // If false then this code is effectively removed
if (t1 == null){
t1 = Timing.createStopWatch("A simple loop measurement").enableStdDev();
}
t1.start();
}
simulateWork();
if (ENABLE_TIMING){ // If false then this code is effectively removed
t1.stop();
}
}
if (ENABLE_TIMING){
Timing.dumpTimings("Results.");
}
private static void simulateWork() {
//this is just a way to get a pseduo-random delay
long delay = System.currentTimeMillis() % 7;
try {
Thread.sleep(10+delay);
}
catch (InterruptedException ignore) {}
}
}
Here the compile-time constant ENABLE_TIMING is used to select whether to include
or exclude the profiling code. If the variable is false there will be no runtime penalty
for having the profiling code because the compiler will not generate it. This is just
a standard side-effect of the Java compiler which depends on ENABLE_TIMING being
a final static boolean.
This technique allows the profiling code to be left in production code with no impact other than the unused declaration of the StopWatch variable.
The above example also shows how standard deviation may be tallied in addition
to average timing.
Without the call to .enableStdDev()
cumulative time and the number of iterations are reported. With the call
average time, standard deviation, and coefficient of variation are reported.
When the code runs the output will look similar to:
Results.
A simple loop measurement (org.mitre.javaTiming.ExampleBetterSimpleTiming.main-21) = 13.957900 ms. avg. (139.579/10) +- 2.344602 coef-of-variation=0.167977
package org.mitre.poorMan.javaTiming;
import java.io.*;
public class ExampleUseOfDerivedComputation {
public static int nBytesWritten;
public static DerivedComputation diskWriteRate;
public static final Double ZERO = new Double(0.0);
public static void main(String[] args) {
new ExampleUseOfDerivedComputation().writeToDisk();
Timing.dumpTimings("");
}
private StopWatch dataWriteTime;
private StopWatch fileOpenTime;
private StopWatch fileCloseTime;
private StopWatch overallTime;
private void writeToDisk(){
Timing.stripBaseName("org.mitre.poorMan.javaTiming.ExampleUseOfDerivedComputation.");
Timing.setNestedTimingEnabled(true);
Timing.registerDerivedComputation("write speed",
diskWriteRate=new DerivedComputation(){
@Override
public String getComputedString() {
Number val = getComputedNumber();
if (val == ZERO) return null;
return val.toString() + " kByte/s";
}
@Override
public Number getComputedNumber() {
if (overallTime.getCount() == 0){
return ZERO;
}
else {
double bytesInEachFile = nBytesWritten / overallTime.getCount();
// getAvg() is in nanoseconds
double writeRateBps = bytesInEachFile / (dataWriteTime.getAvg() * 1e-9) ;
double writeRateKBps = writeRateBps /1000.0;
return new Double(writeRateKBps);
}
}
});
for (int i = 0; i<10; i++){
if (overallTime == null){
overallTime = Timing.createStopWatch("overall time").enableStdDev();
}
overallTime.start();
PrintWriter p = openFile();
writeData(p);
closeFile(p);
overallTime.stop();
}
}
private PrintWriter openFile(){
if (fileOpenTime == null){
fileOpenTime = Timing.createStopWatch("time to open file").enableStdDev();
}
fileOpenTime.start();
PrintWriter p = null;
try {
File file = File.createTempFile("test", ".txt");
p = new PrintWriter(new FileWriter(file));
file.deleteOnExit();
} catch (IOException e) {
e.printStackTrace();
}
fileOpenTime.stop();
return p;
}
private void closeFile(PrintWriter p){
if (fileCloseTime == null){
fileCloseTime = Timing.createStopWatch("time to close file").enableStdDev();
}
fileCloseTime.start();
p.close();
fileCloseTime.stop();
}
private void writeData(PrintWriter p){
if (dataWriteTime == null){
dataWriteTime = Timing.createStopWatch("time to write a block").enableStdDev();
}
dataWriteTime.start();
for (int i = 0; i<1000; i++){
p.println("0123456789");
nBytesWritten += 11; // if we are on Windows we should be incrementing by 12
}
dataWriteTime.stop();
}
}
In the example above it may seem awkward to put the call to Timing.createStopWatch()
down in the body as opposed to above where the variable is created.
This is done intentionally so that a line number can be associated with the StopWatch
which is close to where we actually start the timing. This can be useful later when debugging and analyzing the output.
The example is long but it shows how multiple StopWatches can be used to time an overall activity as well as the parts that make up the overall activity. In this trivial example the parts map directly into 3 different methods, though in general this will not be the case.
This illustrates one of the benefits of this utility - we only get times for what we are interested in, with very little overhead. Generic profiling tools often time each and every call or they randomly sample calls to reduce overhead. Then one has to analyze the output to get to the desired information. Here all the StopWatch start/stop's are timed. Since there are usually only a few of them there isn't much overhead for doing this and there usually isn't much analysis required. Of course this only works for source code that we can instrument and compile.
The last feature is the ability to analyze the profile information by looking at a simple nested timing report. The nesting is defined by the nested activation of the StopWatches - ie, starting and stopping another StopWatch before the previous one has finished. Note that if the nested timing feature is being used then a "child" time must be stopped before before the "parent" is stopped. An error will be logged (but not thrown) if this happens.
In the previous
example we already had nested timing.
There is a StopWatch that measures the overall time and there are 3 "inner" StopWatches
that measure components of the overall time. If nested timing is enabled with Timing.setNestedTimingEnabled(true) then the output will include
an indented "graph" that shows these times indented appropriately. For
the previous example that part of the output appears as:
ROOT
Thread main - 1
overall time (writeToDisk-105) = 98.742 ms. total (10 * 9.874200) +- 14.998643 coef-of-variation=1.518973
time to open file (openFile-130) = 41.858 ms. total (10 * 4.185800) +- 12.576115 coef-of-variation=3.004471
time to write a block (writeData-181) = 54.494 ms. total (10 * 5.449400) +- 3.423832 coef-of-variation=0.628295
time to close file (closeFile-159) = 1.114 ms. total (10 * 0.111400) +- 0.026842 coef-of-variation=0.240951
By default nested timing is disabled and that part of the output is not generated.
Note that the nesting logic attempts to follow nesting across threads. There is still work to be done on this
and you will see some inaccuracies in the graph when there are multiple threads invoked during the execution of
your timing intervals.