/***************************************************************************
* Copyright (C) 2012 by H-Store Project *
* Brown University *
* Massachusetts Institute of Technology *
* Yale University *
* *
* http://hstore.cs.brown.edu/ *
* *
* 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 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 edu.brown.profilers;
import java.io.File;
import java.io.IOException;
import java.util.Collection;
import org.apache.commons.collections15.Buffer;
import org.apache.commons.collections15.buffer.CircularFifoBuffer;
import org.apache.log4j.Logger;
import org.json.JSONArray;
import org.json.JSONException;
import org.json.JSONObject;
import org.json.JSONStringer;
import org.voltdb.catalog.Database;
import edu.brown.logging.LoggerUtil;
import edu.brown.logging.LoggerUtil.LoggerBoolean;
import edu.brown.utils.EventObservable;
import edu.brown.utils.EventObserver;
import edu.brown.utils.JSONSerializable;
import edu.brown.utils.JSONUtil;
/**
* @author pavlo
*/
public class ProfileMeasurement implements JSONSerializable {
private static final Logger LOG = Logger.getLogger(ProfileMeasurement.class);
private static final LoggerBoolean debug = new LoggerBoolean();
private static final LoggerBoolean trace = new LoggerBoolean();
static {
LoggerUtil.attachObserver(LOG, debug, trace);
}
private static final long NULL_MARKER = -1l;
/** The profile type */
private String name;
/** Total amount of time spent processing the profiled section (in ms) */
private long total_time;
/** The number of times that this ProfileMeasurement has been started */
private int invocations = 0;
private Buffer<Long> history = null;
/**
* This marker is used to set when the boundary area of the code we are
* trying to profile starts and stops. When it is zero, the system is
* outside of the profiled area.
*/
private transient long marker = NULL_MARKER;
private transient boolean reset = false;
private transient EventObservable<ProfileMeasurement> start_observable;
private transient EventObservable<ProfileMeasurement> stop_observable;
// ----------------------------------------------------------------------------
// CONSTRUCTORS
// ----------------------------------------------------------------------------
public ProfileMeasurement() {
// For serialization
}
/**
* Constructor
* @param pmtype
*/
public ProfileMeasurement(String pmtype) {
this(pmtype, false);
}
/**
* Constructor
* @param pmtype
* @param history Enable history tracking
*/
public ProfileMeasurement(String pmtype, boolean history) {
this.name = pmtype;
if (history) this.enableHistoryTracking();
this.reset();
}
/**
* Copy constructor
*
* @param orig
*/
public ProfileMeasurement(ProfileMeasurement orig) {
this(orig.name, (orig.history != null));
if (this.history != null) {
this.history.addAll(orig.history);
}
this.appendTime(orig);
}
// ----------------------------------------------------------------------------
// UTILITY METHODS
// ----------------------------------------------------------------------------
public void enableHistoryTracking() {
if (this.history == null) {
synchronized (this) {
if (this.history == null) {
this.history = new CircularFifoBuffer<Long>(10000);
}
} // SYNCH
if (debug.val)
LOG.debug("Enabled history tracking in " + this);
}
}
public void reset() {
if (this.marker != NULL_MARKER) {
this.reset = true;
}
this.total_time = 0;
this.invocations = 0;
if (this.history != null) this.history.clear();
}
public void clear() {
this.marker = NULL_MARKER;
this.invocations = 0;
this.total_time = 0;
if (this.history != null) this.history.clear();
}
/**
* Reset this ProfileMeasurements internal data when an update arrives
* for the given EventObservable
* @param e
*/
public <T> void resetOnEventObservable(EventObservable<T> e) {
e.addObserver(new EventObserver<T>() {
@Override
public void update(EventObservable<T> o, T arg) {
ProfileMeasurement.this.reset();
}
});
}
/**
* Get the profile type name
* @return
*/
public String getName() {
return (this.name);
}
/**
* Get the total amount of time spent in the profiled area in nanoseconds
* @return
*/
public long getTotalThinkTime() {
return (this.total_time);
}
/**
* Get the total amount of time spent in the profiled area in milliseconds
* @return
*/
public double getTotalThinkTimeMS() {
return (this.total_time / 1000000d);
}
/**
* Get the total amount of time spent in the profiled area in seconds
* @return
*/
public double getTotalThinkTimeSeconds() {
return (this.total_time / 1000000d / 1000d);
}
/**
* Get the average think time per invocation in nanoseconds
* @return
*/
public double getAverageThinkTime() {
return (this.invocations > 0 ? this.total_time / (double) this.invocations : 0d);
}
/**
* Get the average think time per invocation in milliseconds
* @return
*/
public double getAverageThinkTimeMS() {
return (this.getAverageThinkTime() / 1000000d);
}
/**
* Get the total number of times this object was started
* @return
*/
public int getInvocations() {
return (this.invocations);
}
protected long getMarker() {
return (this.marker);
}
public Collection<Long> getHistory(Collection<Long> to_fill) {
to_fill.addAll(this.history);
return (to_fill);
}
// ----------------------------------------------------------------------------
// START METHODS
// ----------------------------------------------------------------------------
/**
* Main method for stop this ProfileMeasurement from recording time
*
* @return this
*/
public ProfileMeasurement start(long timestamp) {
assert (this.marker == NULL_MARKER) :
String.format("Trying to start %s before it was stopped!", this.name);
if (debug.val)
LOG.debug(String.format("START %s", this));
this.marker = timestamp;
this.invocations++;
if (this.start_observable != null)
this.start_observable.notifyObservers(this);
return (this);
}
public ProfileMeasurement start() {
return (this.start(getTime()));
}
public boolean isStarted() {
return (this.marker != NULL_MARKER);
}
public void addStartObserver(EventObserver<ProfileMeasurement> observer) {
if (this.start_observable == null) {
synchronized (this) {
if (this.start_observable == null) {
this.start_observable = new EventObservable<ProfileMeasurement>();
}
} // SYNCH
}
this.start_observable.addObserver(observer);
}
// ----------------------------------------------------------------------------
// STOP METHODS
// ----------------------------------------------------------------------------
/**
* Main method for stop this ProfileMeasurement from recording time We will
* check to make sure that this handle was started first
*
* @return this
*/
public ProfileMeasurement stop(long timestamp) {
if (this.reset) {
this.reset = false;
this.marker = NULL_MARKER;
return (this);
}
if (debug.val)
LOG.debug(String.format("STOP %s", this));
assert (this.marker != NULL_MARKER) :
String.format("Trying to stop %s before it was started!", this.name);
long added = (timestamp - this.marker);
if (added < 0) {
LOG.warn(String.format("Invalid stop timestamp for %s [timestamp=%d, marker=%d, added=%d]",
this.name, timestamp, this.marker, added));
} else {
this.total_time += added;
if (this.history != null) this.history.add(added);
}
this.marker = NULL_MARKER;
if (this.stop_observable != null)
this.stop_observable.notifyObservers(this);
// if (type == Type.JAVA)
// LOG.info(String.format("STOP %s [time=%d, id=%d]", this.type, added,
// this.hashCode()));
return (this);
}
public ProfileMeasurement stop() {
return (this.stop(getTime()));
}
public ProfileMeasurement stopIfStarted() {
return this.stopIfStarted(getTime());
}
public ProfileMeasurement stopIfStarted(long timestamp) {
if (this.isStarted()) this.stop(timestamp);
return (this);
}
public void addStopObserver(EventObserver<ProfileMeasurement> observer) {
if (this.stop_observable == null) {
synchronized (this) {
if (this.stop_observable == null) {
this.stop_observable = new EventObservable<ProfileMeasurement>();
}
} // SYNCH
}
this.stop_observable.addObserver(observer);
}
// ----------------------------------------------------------------------------
// UTILITY METHODS
// ----------------------------------------------------------------------------
public ProfileMeasurement restart() {
long timestamp = ProfileMeasurement.getTime();
this.stopIfStarted(timestamp).start(timestamp);
return (this);
}
public ProfileMeasurement decrementTime(ProfileMeasurement other, boolean checkType) {
assert(other != null);
if (checkType) assert(this.name == other.name);
this.total_time = Math.max(0, this.total_time - other.total_time);
this.invocations = Math.max(0, this.invocations - other.invocations);
return (this);
}
public ProfileMeasurement decrementTime(ProfileMeasurement other) {
return (this.decrementTime(other, false));
}
public ProfileMeasurement appendTime(ProfileMeasurement other) {
assert(other != null);
this.total_time += other.total_time;
this.marker = other.marker;
this.invocations += other.invocations;
return (this);
}
/**
* Append the think time without locking the marker. This is the preferred
* way to update the ProfileMeasurement when multiple threads are using it.
* @param start
* @param stop
* @param invocations
*/
public void appendTime(long start, long stop, int invocations) {
assert(start >= 0);
assert(stop >= 0);
this.total_time += (stop - start);
this.invocations += invocations;
}
/**
* Append the think time without locking the marker. This is the preferred
* way to update the ProfileMeasurement when multiple threads are using it.
* @param start
* @param stop
*/
public void appendTime(long start, long stop) {
this.appendTime(start, stop, 1);
}
/**
* Append the think time without locking the marker. This is the preferred
* way to update the ProfileMeasurement when multiple threads are using it.
* @param start
*/
public void appendTime(long start) {
this.appendTime(start, getTime(), 1);
}
/**
* Return the current time in nano-seconds
*
* @return
*/
public static long getTime() {
// return System.currentTimeMillis();
return System.nanoTime();
}
// --------------------------------------------------------------------------------------------
// DEBUG METHODS
// --------------------------------------------------------------------------------------------
@Override
public String toString() {
return (this.debug(false));
}
public String debug() {
return this.debug(true);
}
private String debug(boolean verbose) {
String prefix = this.name + "/" + this.hashCode();
if (verbose) {
return (String.format("%s[total=%d, marker=%s, invocations=%d, avg=%.2f ms]",
prefix,
this.total_time,
this.marker,
this.invocations,
this.getAverageThinkTimeMS()));
} else {
return (prefix);
}
}
// --------------------------------------------------------------------------------------------
// SERIALIZATION METHODS
// --------------------------------------------------------------------------------------------
@Override
public void load(File input_path, Database catalog_db) throws IOException {
JSONUtil.load(this, catalog_db, input_path);
}
@Override
public void save(File output_path) throws IOException {
JSONUtil.save(this, output_path);
}
@Override
public String toJSONString() {
return (JSONUtil.toJSONString(this));
}
@Override
public void toJSON(JSONStringer stringer) throws JSONException {
stringer.key("NAME").value(this.name);
stringer.key("TIME").value(this.total_time);
stringer.key("INVOCATIONS").value(this.invocations);
if (this.history != null) {
stringer.key("HISTORY").array();
for (long val : this.history) {
stringer.value(val);
} // FOR
stringer.endArray();
}
}
@Override
public void fromJSON(JSONObject json_object, Database catalog_db) throws JSONException {
this.name = json_object.getString("NAME");
this.total_time = json_object.getLong("TIME");
this.invocations = json_object.getInt("INVOCATIONS");
if (json_object.has("HISTORY")) {
this.history = null;
this.enableHistoryTracking();
JSONArray json_arr = json_object.getJSONArray("HISTORY");
for (int i = 0, cnt = json_arr.length(); i < cnt; i++) {
this.history.add(json_arr.getLong(i));
} // FOR
}
}
}