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}