001/*
002 * The contents of this file are subject to the terms of the Common Development and
003 * Distribution License (the License). You may not use this file except in compliance with the
004 * License.
005 *
006 * You can obtain a copy of the License at legal/CDDLv1.0.txt. See the License for the
007 * specific language governing permission and limitations under the License.
008 *
009 * When distributing Covered Software, include this CDDL Header Notice in each file and include
010 * the License file at legal/CDDLv1.0.txt. If applicable, add the following below the CDDL
011 * Header, with the fields enclosed by brackets [] replaced by your own identifying
012 * information: "Portions Copyright [year] [name of copyright owner]".
013 *
014 * Copyright 2010–2011 ApexIdentity Inc.
015 * Portions Copyright 2011-2014 ForgeRock AS.
016 */
017
018package org.forgerock.openig.log;
019
020import static java.util.concurrent.TimeUnit.*;
021
022/**
023 * Records elapsed time in a log in milliseconds.
024 */
025public class LogTimer {
026
027    /** The time that the timer was started. */
028    private long started = Long.MIN_VALUE; // indicates the timer has not been started
029
030    /** The logger to record log entries to. */
031    private final Logger logger;
032
033    /** The event (within the source) that is being timed. */
034    private final String event;
035
036    /** The log level to log timer events with. */
037    private final LogLevel level;
038
039    private long paused = Long.MIN_VALUE; // indicates the timer has not been paused
040
041    /** Time spend between consecutive pause() and resume() calls. */
042    private long ignorable = 0;
043
044    /**
045     * Constructs a new timer with a logging level of {@link LogLevel#STAT STAT}.
046     *
047     * @param logger the sink to record timer log entries to.
048     */
049    public LogTimer(Logger logger) {
050        this(logger, LogLevel.STAT);
051    }
052
053    /**
054     * Constructs a new timer to log events at a specified logging level.
055     *
056     * @param logger the sink to record timer log entries to.
057     * @param level the logging level to record timer log entries with.
058     */
059    public LogTimer(Logger logger, LogLevel level) {
060        this(logger, level, null);
061    }
062
063    /**
064     * Constructs a new timer to log events of a specific type at a specific logging level.
065     *
066     * @param logger the sink to record timer log entries to.
067     * @param level the logging level to record timer log entries with.
068     * @param event the event being timed.
069     */
070    public LogTimer(Logger logger, LogLevel level, String event) {
071        // avoid call to nanoTime improbably yielding Long.MIN_VALUE
072        System.nanoTime();
073        this.logger = logger;
074        this.event = event;
075        this.level = level;
076    }
077
078    /**
079     * Starts the timer. Records a log entry indicating the timer has been started.
080     *
081     * @return this timer instance.
082     */
083    public LogTimer start() {
084        if (logger != null) {
085            logger.log(logger.createEntry("started", level, "Started"));
086        }
087        started = System.nanoTime();
088        return this;
089    }
090
091    /**
092     * Stops the timer and records the elapsed time(s) in a metric.
093     */
094    public void stop() {
095        long stopped = System.nanoTime();
096        if (logger != null && started != Long.MIN_VALUE) {
097            long elapsed = MILLISECONDS.convert(stopped - started, NANOSECONDS);
098            LogMetric metric = new LogMetric(elapsed, "ms");
099            logger.log(logger.createEntry("elapsed", level, "Elapsed time: " + metric, metric));
100            if (ignorable > 0) {
101                // Log the elapsed time inside an object (without the summed pause times)
102                long ignoredMs = MILLISECONDS.convert(ignorable, NANOSECONDS);
103                LogMetric within = new LogMetric(elapsed - ignoredMs, "ms");
104                logger.log(logger.createEntry("elapsed-within",
105                                              level,
106                                              "Elapsed time (within the object): " + within,
107                                              within));
108            }
109        }
110    }
111
112    /**
113     * Mark the beginning of a pause in the current timer.
114     * Will only do something when:
115     * <ul>
116     *     <li>the timer has been started</li>
117     *     <li>the timer is <b>not</b> currently paused</li>
118     * </ul>
119     *
120     * @return this timer
121     */
122    public LogTimer pause() {
123        // Ensure the timer has been started
124        if (started != Long.MIN_VALUE) {
125            // Ignore if pause is called multiple times without resume
126            if (paused == Long.MIN_VALUE) {
127                paused = System.nanoTime();
128            }
129        }
130        return this;
131    }
132
133    /**
134     * Mark the end of a pause in the current timer (sum up all of the pauses lengths).
135     * Will only do something when the timer is currently paused. It will also reset the pause beginning marker
136     * to its default value in order to allow multiple pause/resume calls.
137     *
138     * @return this timer
139     */
140    public LogTimer resume() {
141        // Ensure the timer has been paused
142        if (paused != Long.MIN_VALUE) {
143            long resumed = System.nanoTime();
144            ignorable += (resumed - paused);
145            paused = Long.MIN_VALUE;
146        }
147        return this;
148    }
149
150    private String source(String event) {
151        StringBuilder sb = new StringBuilder();
152        if (this.event != null) {
153            sb.append(this.event).append('.');
154        }
155        sb.append(event);
156        return sb.toString();
157    }
158}