/*
* Licensed to the Apache Software Foundation (ASF) under one
* or more contributor license agreements. See the NOTICE file
* distributed with this work for additional information
* regarding copyright ownership. The ASF licenses this file
* to you under the Apache License, Version 2.0 (the
* "License"); you may not use this file except in compliance
* with the License. You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing,
* software distributed under the License is distributed on an
* "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
* KIND, either express or implied. See the License for the
* specific language governing permissions and limitations
* under the License.
*/
package org.apache.sling.engine.impl.request;
import java.io.PrintWriter;
import java.util.ArrayList;
import java.util.HashMap;
import java.util.Iterator;
import java.util.List;
import java.util.Map;
import javax.servlet.http.HttpServletRequest;
import org.apache.sling.api.request.RequestProgressTracker;
/**
* The <code>SlingRequestProgressTracker</code> class provides the
* functionality to track the progress of request processing. Instances of this
* class are provided through the
* {@link org.apache.sling.api.SlingHttpServletRequest#getRequestProgressTracker()}
* method.
* <p>
* The following functionality is provided:
* <ol>
* <li>Track the progress of request processing through the
* {@link #log(String)} and {@link #log(String, Object...)} methods.
* <li>Ability to measure and track processing times of parts of request
* processing through the {@link #startTimer(String)} and
* {@link #logTimer(String)} methods.
* <li>Dumping the recording messages through the
* {@link #dump(PrintWriter)} method.
* <li>Resetting the tracker through the {@link #reset()} method.
* </ol>
* <p>
* <b>Tracking Request Processing</b>
* <p>
* As the request being processed, certain steps may be tracked by calling
* either of the <code>log</code> methods. A tracking entry consists of a time
* stamp managed by this class, and a tracking message noting the actual step being
* tracked.
* <p>
* <b>Timing Processing Steps</b>
* </p>
* Certain steps during request processing may need to be timed in that the time
* required for processing should be recorded. Instances of this class maintain
* a map of named timers. Each timer is started (initialized or reset) by
* calling the {@link #startTimer(String)} method. This method just records the
* starting time of the named timer.
* <p>
* To record the number of milliseconds ellapsed since a timer has been started,
* the {@link #logTimer(String)} method may be called. This method logs the
* tracking entry with message
* consisting of the name of the timer and the number of milliseconds ellapsed
* since the timer was last {@link #startTimer(String) started}. The
* {@link #logTimer(String)} method may be called multiple times to record
* several timed steps.
* <p>
* Additional information can be logged using the {@link #logTimer(String, String, Object...)}
* method.
* <p>
* Calling the {@link #startTimer(String)} method with the name of timer which
* already exists, resets the start time of the named timer to the current
* system time.
* <p>
* <b>Dumping Tracking Entries</b>
* <p>
* The {@link #dump(PrintWriter)} methods writes all tracking entries to the given
* <code>PrintWriter</code>. Each entry is written on a single line
* consisting of the following fields:
* <ol>
* <li>The number of milliseconds since the last {@link #reset()} (or creation)
* of this timer.
* <li>The absolute time of the timer in parenthesis.
* <li>The entry message
* </ol>
*/
public class SlingRequestProgressTracker implements RequestProgressTracker {
/**
* The name of the timer tracking the processing time of the complete
* process.
*/
private static final String REQUEST_PROCESSING_TIMER = "Request Processing";
/** Prefix for log messages */
private static final String LOG_PREFIX = "LOG ";
/** Prefix for comment messages */
private static final String COMMENT_PREFIX = "COMMENT ";
/** TIMER_END format explanation */
private static final String TIMER_END_FORMAT = "{<elapsed microseconds>,<timer name>} <optional message>";
/** The leading nanosecond number is left-padded with white-space to this width. */
private static final int PADDING_WIDTH = 7;
/**
* The system time at creation of this instance or the last {@link #reset()}.
*/
private long processingStart;
/**
* The system time when {@link #done()} was called or -1 while processing is in progress.
*/
private long processingEnd;
/**
* The list of tracking entries.
*/
private final List<TrackingEntry> entries = new ArrayList<TrackingEntry>();
/**
* Map of named timers indexed by timer name storing the system time of
* start of the respective timer.
*/
private final Map<String, Long> namedTimerEntries = new HashMap<String, Long>();
private final FastMessageFormat messageFormat = new FastMessageFormat();
/**
* Creates a new request progress tracker.
*/
public SlingRequestProgressTracker() {
this(null);
}
/**
* Creates a new request progress tracker and logs initial messages about the supplied request
*/
public SlingRequestProgressTracker(HttpServletRequest request) {
reset();
if(request != null) {
log("Method={0}, PathInfo={1}", request.getMethod(), request.getPathInfo());
}
}
/**
* Resets this timer by removing all current entries and timers and adds an
* initial timer entry
*/
public void reset() {
// remove all entries
entries.clear();
namedTimerEntries.clear();
// enter initial messages
processingStart = startTimerInternal(REQUEST_PROCESSING_TIMER);
processingEnd = -1;
entries.add(new TrackingEntry(COMMENT_PREFIX + "timer_end format is " + TIMER_END_FORMAT));
}
/**
* @see org.apache.sling.api.request.RequestProgressTracker#getMessages()
*/
public Iterator<String> getMessages() {
return new Iterator<String>() {
private final Iterator<TrackingEntry> entryIter = entries.iterator();
public boolean hasNext() {
return entryIter.hasNext();
}
public String next() {
// throws NoSuchElementException if no entries any more
final TrackingEntry entry = entryIter.next();
final long offset = entry.getTimeStamp() - getTimeStamp();
return formatMessage(offset, entry.getMessage());
}
public void remove() {
throw new UnsupportedOperationException("remove");
}
};
}
private String formatMessage(long offset, String message) {
// Set exact length to avoid array copies within StringBuilder
final StringBuilder sb = new StringBuilder(PADDING_WIDTH + 1 + message.length() + 1);
final String offsetStr = Long.toString(offset / 1000);
for (int i = PADDING_WIDTH - offsetStr.length(); i > 0; i--) {
sb.append(' ');
}
sb.append(offsetStr).append(' ').append(message).append('\n');
return sb.toString();
}
/**
* Dumps the process timer entries to the given writer, one entry per line.
* See the class comments for the rough format of each message line.
*/
public void dump(final PrintWriter writer) {
logTimer(REQUEST_PROCESSING_TIMER,
"Dumping SlingRequestProgressTracker Entries");
final StringBuilder sb = new StringBuilder();
final Iterator<String> messages = getMessages();
while (messages.hasNext()) {
sb.append(messages.next());
}
writer.print(sb.toString());
}
/** Creates an entry with the given message. */
public void log(String message) {
entries.add(new TrackingEntry(LOG_PREFIX + message));
}
/** Creates an entry with the given entry tag and message */
public void log(String format, Object... args) {
String message = messageFormat.format(format, args);
entries.add(new TrackingEntry(LOG_PREFIX + message));
}
/**
* Starts a named timer. If a timer of the same name already exists, it is
* reset to the current time.
*/
public void startTimer(String name) {
startTimerInternal(name);
}
/**
* Start the named timer and returns the start time in milliseconds.
* Logs a message with format
* <pre>
* TIMER_START{<name>} <optional message>
* </pre>
*/
private long startTimerInternal(String name) {
long timer = System.nanoTime();
namedTimerEntries.put(name, timer);
entries.add(new TrackingEntry(timer, "TIMER_START{" + name + "}"));
return timer;
}
/**
* Log a timer entry, including start, end and elapsed time.
*/
public void logTimer(String name) {
if (namedTimerEntries.containsKey(name)) {
logTimerInternal(name, null, namedTimerEntries.get(name));
}
}
/**
* Log a timer entry, including start, end and elapsed time.
*/
public void logTimer(String name, String format, Object... args) {
if (namedTimerEntries.containsKey(name)) {
logTimerInternal(name, messageFormat.format(format, args), namedTimerEntries.get(name));
}
}
/**
* Log a timer entry, including start, end and elapsed time using TIMER_END_FORMAT
*/
private void logTimerInternal(String name, String msg, long startTime) {
final StringBuilder sb = new StringBuilder();
sb.append("TIMER_END{");
sb.append((System.nanoTime() - startTime) / 1000);
sb.append(',');
sb.append(name);
sb.append('}');
if(msg != null) {
sb.append(' ');
sb.append(msg);
}
entries.add(new TrackingEntry(sb.toString()));
}
public void done() {
if(processingEnd != -1) return;
logTimer(REQUEST_PROCESSING_TIMER, REQUEST_PROCESSING_TIMER);
processingEnd = System.nanoTime();
}
private long getTimeStamp() {
return processingStart;
}
public long getDuration() {
if (processingEnd != -1) {
return processingEnd - processingStart;
}
return System.nanoTime() - processingStart;
}
/** Process tracker entry keeping timestamp, tag and message */
private static class TrackingEntry {
// creation time stamp
private final long timeStamp;
// tracking message
private final String message;
TrackingEntry(String message) {
this.timeStamp = System.nanoTime();
this.message = message;
}
TrackingEntry(long timeStamp, String message) {
this.timeStamp = timeStamp;
this.message = message;
}
long getTimeStamp() {
return timeStamp;
}
String getMessage() {
return message;
}
}
}