Package org.mitre.poorMan.javaTiming

A tool to help profile the execution-time characteristics of Java code.

See: Description

Package org.mitre.poorMan.javaTiming Description

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:

A Note About Java Nanosecond Timing

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).

Simple Usage Example

The following code fragment illustrates the most basic use of the Timing class:
        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) {}
        }
The output of this test (with the Log4j preamble omitted) is:
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.

Timing

The following example goes beyond the simple example to show a recommended pattern for leaving the timing code embedded in a deployed application with little overhead. The example also shows how a statistic may be used to take repeated measurements.
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

Derived Computations and Metrics

Sometimes you want to compute a metric that depends on timing information, such as the estimated number of instructions executed per second, or the number of bytes per second transmitted. The package provides a way to register your own dependent metrics and calculations. The following example shows this:
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.

Nested Timing

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.

External Library Dependencies

This uses SLF4J and Log4J.