Java example source code file (Profiler.java)

This example Java source code file (Profiler.java) is included in the alvinalexander.com "Java Source Code Warehouse" project. The intent of this project is to help you "Learn Java by Example" ^TM.

Learn more about this Java project at its project page.

Java - Java tags/keywords

arraylist, durationunit, elapsed_time, illegalstateexception, list, logger, profiler, profilerregistry, stopwatch, string, stringbuilder, timeinstrument, top_profiler_first_prefix, total_elapsed, util

The Profiler.java Java example source code

/**
 * Copyright (c) 2004-2011 QOS.ch
 * All rights reserved.
 *
 * Permission is hereby granted, free  of charge, to any person obtaining
 * a  copy  of this  software  and  associated  documentation files  (the
 * "Software"), to  deal in  the Software without  restriction, including
 * without limitation  the rights to  use, copy, modify,  merge, publish,
 * distribute,  sublicense, and/or sell  copies of  the Software,  and to
 * permit persons to whom the Software  is furnished to do so, subject to
 * the following conditions:
 *
 * The  above  copyright  notice  and  this permission  notice  shall  be
 * included in all copies or substantial portions of the Software.
 *
 * THE  SOFTWARE IS  PROVIDED  "AS  IS", WITHOUT  WARRANTY  OF ANY  KIND,
 * EXPRESS OR  IMPLIED, INCLUDING  BUT NOT LIMITED  TO THE  WARRANTIES OF
 * MERCHANTABILITY,    FITNESS    FOR    A   PARTICULAR    PURPOSE    AND
 * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE
 * LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION
 * OF CONTRACT, TORT OR OTHERWISE,  ARISING FROM, OUT OF OR IN CONNECTION
 * WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
 *
 */
package org.slf4j.profiler;

import java.util.ArrayList;
import java.util.List;

import org.slf4j.Logger;
import org.slf4j.Marker;
import org.slf4j.MarkerFactory;

// +  Profiler [BAS]
// |-- elapsed time            [doX]     0 milliseconds.
// |-- elapsed time        [doYYYYY]    56 milliseconds.
// |--+ Profiler Y
//    |-- elapsed time            [doZ]    21 milliseconds.
//    |-- elapsed time            [doZ]    21 milliseconds.
//    |-- Total elapsed time        [Y]    78 milliseconds.
// |-- elapsed time            [doZ]    21 milliseconds.
// |-- Total elapsed time      [BAS]    78 milliseconds.

/**
 * A poor man's profiler to measure the time elapsed performing some lengthy
 * task.
 * 
 * @author Ceki Gülcü
 */
public class Profiler implements TimeInstrument {

    final static String PROFILER_MARKER_NAME = "PROFILER";

    final static int MIN_SW_NAME_LENGTH = 24;
    final static int MIN_SW_ELAPSED_TIME_NUMBER_LENGTH = 9;

    final String name;
    final StopWatch globalStopWatch;

    List<TimeInstrument> childTimeInstrumentList = new ArrayList();

    // optional field
    ProfilerRegistry profilerRegistry;
    // optional field
    Logger logger;

    public Profiler(String name) {
        this.name = name;
        this.globalStopWatch = new StopWatch(name);
    }

    public String getName() {
        return name;
    }

    public ProfilerRegistry getProfilerRegistry() {
        return profilerRegistry;
    }

    public void registerWith(ProfilerRegistry profilerRegistry) {
        if (profilerRegistry == null) {
            return;
        }
        this.profilerRegistry = profilerRegistry;
        profilerRegistry.put(this);
    }

    public Logger getLogger() {
        return logger;
    }

    public void setLogger(Logger logger) {
        this.logger = logger;
    }

    /**
     * Starts a child stop watch and stops any previously started time
     * instruments.
     */
    public void start(String name) {
        stopLastTimeInstrument();
        StopWatch childSW = new StopWatch(name);
        childTimeInstrumentList.add(childSW);
    }

    public Profiler startNested(String name) {
        stopLastTimeInstrument();
        Profiler nestedProfiler = new Profiler(name);
        nestedProfiler.registerWith(profilerRegistry);
        nestedProfiler.setLogger(logger);
        childTimeInstrumentList.add(nestedProfiler);
        return nestedProfiler;
    }

    TimeInstrument getLastTimeInstrument() {
        if (childTimeInstrumentList.size() > 0) {
            return childTimeInstrumentList.get(childTimeInstrumentList.size() - 1);
        } else {
            return null;
        }
    }

    void stopLastTimeInstrument() {
        TimeInstrument last = getLastTimeInstrument();
        if (last != null) {
            last.stop();
        }
    }

    // void stopNestedProfilers() {
    // for (Object child : childTimeInstrumentList) {
    // if (child instanceof Profiler)
    // ((Profiler) child).stop();
    // }
    // }

    public long elapsedTime() {
        return globalStopWatch.elapsedTime();
    }

    public TimeInstrument stop() {
        stopLastTimeInstrument();
        globalStopWatch.stop();
        return this;
    }

    public TimeInstrumentStatus getStatus() {
        return globalStopWatch.status;
    }

    /**
     * This method is used in tests.
     */
    void sanityCheck() throws IllegalStateException {
        if (getStatus() != TimeInstrumentStatus.STOPPED) {
            throw new IllegalStateException("time instrument [" + getName() + " is not stopped");
        }

        long totalElapsed = globalStopWatch.elapsedTime();
        long childTotal = 0;

        for (TimeInstrument ti : childTimeInstrumentList) {
            childTotal += ti.elapsedTime();
            if (ti.getStatus() != TimeInstrumentStatus.STOPPED) {
                throw new IllegalStateException("time instrument [" + ti.getName() + " is not stopped");
            }
            if (ti instanceof Profiler) {
                Profiler nestedProfiler = (Profiler) ti;
                nestedProfiler.sanityCheck();
            }
        }
        if (totalElapsed < childTotal) {
            throw new IllegalStateException("children have a higher accumulated elapsed time");
        }
    }

    static String TOP_PROFILER_FIRST_PREFIX = "+";
    static String NESTED_PROFILER_FIRST_PREFIX = "|---+";
    static String TOTAL_ELAPSED = " Total        ";
    static String SUBTOTAL_ELAPSED = " Subtotal     ";
    static String ELAPSED_TIME = " elapsed time ";

    public void print() {
        System.out.println(toString());
    }

    @Override
    public String toString() {
        DurationUnit du = Util.selectDurationUnitForDisplay(globalStopWatch);
        return buildProfilerString(du, TOP_PROFILER_FIRST_PREFIX, TOTAL_ELAPSED, "");
    }

    public void log() {
        Marker profilerMarker = MarkerFactory.getMarker(PROFILER_MARKER_NAME);
        if (logger == null) {
            throw new NullPointerException("If you invoke the log() method, then you must associate a logger with this profiler.");
        }
        if (logger.isDebugEnabled(profilerMarker)) {
            DurationUnit du = Util.selectDurationUnitForDisplay(globalStopWatch);
            String r = buildProfilerString(du, TOP_PROFILER_FIRST_PREFIX, TOTAL_ELAPSED, "");
            logger.debug(profilerMarker, SpacePadder.LINE_SEP + r);
        }
    }

    /**
     * Return a copy of the child instrument list for this Profiler instance.
     * 
     * @return a copy of this instance's child time instrument list
     * @since 1.5.9
     */
    public List<TimeInstrument> getCopyOfChildTimeInstruments() {
        List<TimeInstrument> copy = new ArrayList(childTimeInstrumentList);
        return copy;
    }

    /**
     * Return a copy of the global stopwath of this Profiler instance.
     * 
     * @return a copy of this instance's global stop watch
     * @since 1.5.9
     */
    public StopWatch getCopyOfGlobalStopWatch() {
        StopWatch copy = new StopWatch(globalStopWatch);
        return copy;
    }

    private String buildProfilerString(DurationUnit du, String firstPrefix, String label, String indentation) {
        StringBuilder buf = new StringBuilder();

        buf.append(firstPrefix);
        buf.append(" Profiler [");
        buf.append(name);
        buf.append("]");
        buf.append(SpacePadder.LINE_SEP);
        for (TimeInstrument child : childTimeInstrumentList) {
            if (child instanceof StopWatch) {
                buildStopWatchString(buf, du, ELAPSED_TIME, indentation, (StopWatch) child);
            } else if (child instanceof Profiler) {
                Profiler profiler = (Profiler) child;
                String subString = profiler.buildProfilerString(du, NESTED_PROFILER_FIRST_PREFIX, SUBTOTAL_ELAPSED, indentation + "    ");
                buf.append(subString);
                buildStopWatchString(buf, du, ELAPSED_TIME, indentation, profiler.globalStopWatch);
            }
        }
        buildStopWatchString(buf, du, label, indentation, globalStopWatch);
        return buf.toString();
    }

    private static void buildStopWatchString(StringBuilder buf, DurationUnit du, String prefix, String indentation, StopWatch sw) {

        buf.append(indentation);
        buf.append("|--");
        buf.append(prefix);
        SpacePadder.leftPad(buf, "[" + sw.getName() + "]", MIN_SW_NAME_LENGTH);
        buf.append(" ");
        String timeStr = Util.durationInDurationUnitsAsStr(sw.elapsedTime(), du);
        SpacePadder.leftPad(buf, timeStr, MIN_SW_ELAPSED_TIME_NUMBER_LENGTH);
        buf.append(" ");
        Util.appendDurationUnitAsStr(buf, du);
        buf.append(SpacePadder.LINE_SEP);
    }
}