Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with
or
.
Download ZIP
Browse files

Added INFO level messages to better understand statistics tracking (S…

…toreStats, SocketClientStats, Histogram) behavior. Expect to remove most of these messages after debugging.

src/java/voldemort/store/stats/Histogram.java
- one more check to harden the imnplementation of insert

src/java/voldemort/store/stats/RequestCounter.java
- durationMs from int to long
- print out timing of histogram reset (q95, q99, reset)
  • Loading branch information...
commit b4994bbe34b7c3dc613faea27096c617002547f4 1 parent 90aabc3
@jayjwylie jayjwylie authored
View
1  src/java/log4j.properties
@@ -12,6 +12,7 @@ log4j.appender.stdout.layout.ConversionPattern=[%d{ABSOLUTE} %c] %p %m [%t]%n
log4j.logger=INFO
log4j.logger.httpclient.wire=INFO
log4j.logger.org.mortbay.log=WARN
+log4j.logger.voldemort.server=INFO
log4j.logger.voldemort.store.routed=INFO
log4j.logger.voldemort.server.niosocket=INFO
log4j.logger.voldemort.utils=INFO
View
9 src/java/voldemort/store/stats/ClientSocketStats.java
@@ -22,6 +22,8 @@
import java.util.concurrent.atomic.AtomicInteger;
import java.util.concurrent.atomic.AtomicLong;
+import org.apache.log4j.Logger;
+
import voldemort.store.socket.SocketDestination;
import voldemort.store.socket.clientrequest.ClientRequestExecutor;
import voldemort.utils.JmxUtils;
@@ -73,6 +75,7 @@
private final Histogram resourceRequestQueueLengthHistogram = new Histogram(250, 1);
private final int jmxId;
+ private static final Logger logger = Logger.getLogger(ClientSocketStats.class.getName());
/**
* To construct a per node stats object
@@ -91,6 +94,9 @@ public ClientSocketStats(ClientSocketStats parent,
this.destination = destination;
this.pool = pool;
this.jmxId = jmxId;
+
+ logger.info("Constructed ClientSocketStatsStats object (" + System.identityHashCode(this)
+ + ") with parent object(" + System.identityHashCode(parent) + ")");
}
/**
@@ -104,6 +110,9 @@ public ClientSocketStats(int jmxId) {
this.destination = null;
this.pool = null;
this.jmxId = jmxId;
+
+ logger.info("Constructed ClientSocketStatsStats object (" + System.identityHashCode(this)
+ + ") with parent object(" + System.identityHashCode(parent) + ")");
}
/* get per node stats, create one if not exist */
View
5 src/java/voldemort/store/stats/Histogram.java
@@ -52,6 +52,7 @@ public Histogram(int nBuckets, int step, long resetIntervalMs) {
* @param step The size (width) of each bucket
*/
public Histogram(int nBuckets, int step) {
+ logger.info("Constructing a histogram with " + nBuckets + " buckets.");
this.nBuckets = nBuckets;
this.step = step;
this.upperBound = step * nBuckets;
@@ -87,9 +88,9 @@ public synchronized void insert(long data) {
} else {
index = data / step;
}
- if(index >= nBuckets) {
+ if(index < 0 || index >= nBuckets) {
// This is dead code. Defend against code changes in future.
- logger.error(data + " can't be bucketed because index overflowed number of buckets!");
+ logger.error(data + " can't be bucketed because index is not in range [0,nBuckets).");
return;
}
buckets[(int) index]++;
View
46 src/java/voldemort/store/stats/RequestCounter.java
@@ -2,6 +2,8 @@
import java.util.concurrent.atomic.AtomicReference;
+import org.apache.log4j.Logger;
+
import voldemort.utils.SystemTime;
import voldemort.utils.Time;
@@ -14,41 +16,43 @@
public class RequestCounter {
private final AtomicReference<Accumulator> values;
- private final int durationMS;
+ private final long durationMs;
private final Time time;
private final Histogram histogram;
private volatile long q95LatencyMs;
private volatile long q99LatencyMs;
private boolean useHistogram;
+ private static final Logger logger = Logger.getLogger(RequestCounter.class.getName());
+
/**
- * @param durationMS specifies for how long you want to maintain this
+ * @param durationMs specifies for how long you want to maintain this
* counter (in milliseconds).
*/
- public RequestCounter(int durationMS) {
- this(durationMS, SystemTime.INSTANCE, false);
+ public RequestCounter(long durationMs) {
+ this(durationMs, SystemTime.INSTANCE, false);
}
/**
- * @param durationMS specifies for how long you want to maintain this
+ * @param durationMs specifies for how long you want to maintain this
* counter (in milliseconds). useHistogram indicates that this
* counter should also use a histogram.
*/
- public RequestCounter(int durationMS, boolean useHistogram) {
- this(durationMS, SystemTime.INSTANCE, useHistogram);
+ public RequestCounter(long durationMs, boolean useHistogram) {
+ this(durationMs, SystemTime.INSTANCE, useHistogram);
}
/**
* For testing request expiration via an injected time provider
*/
- RequestCounter(int durationMS, Time time) {
- this(durationMS, time, false);
+ RequestCounter(long durationMs, Time time) {
+ this(durationMs, time, false);
}
- RequestCounter(int durationMS, Time time, boolean useHistogram) {
+ RequestCounter(long durationMs, Time time, boolean useHistogram) {
this.time = time;
this.values = new AtomicReference<Accumulator>(new Accumulator());
- this.durationMS = durationMS;
+ this.durationMs = durationMs;
this.q95LatencyMs = 0;
this.q99LatencyMs = 0;
this.useHistogram = useHistogram;
@@ -98,8 +102,8 @@ public String getDisplayAverageTimeInMs() {
return String.format("%.4f", getAverageTimeInMs());
}
- public int getDuration() {
- return durationMS;
+ public long getDuration() {
+ return durationMs;
}
public long getMaxLatencyInMs() {
@@ -111,11 +115,16 @@ private void maybeResetHistogram() {
return;
Accumulator accum = values.get();
long now = time.getMilliseconds();
- if(now - accum.startTimeMS > durationMS) {
+ if(now - accum.startTimeMS > durationMs) {
+ long startTimeNs = System.nanoTime();
// Reset the histogram
q95LatencyMs = histogram.getQuantile(0.95);
q99LatencyMs = histogram.getQuantile(0.99);
histogram.reset();
+ // TODO: Make this DEBUG level
+ logger.info("Histogram (" + System.identityHashCode(histogram)
+ + ") : reset, Q95, & Q99 took " + (System.nanoTime() - startTimeNs)
+ + " ns.");
}
}
@@ -127,7 +136,7 @@ private Accumulator getValidAccumulator() {
/*
* if still in the window, just return it
*/
- if(now - accum.startTimeMS <= durationMS) {
+ if(now - accum.startTimeMS <= durationMs) {
return accum;
}
@@ -192,6 +201,8 @@ public void addRequest(long timeNS,
if(values.compareAndSet(oldv, newv))
return;
}
+ // TODO: Make this DEBUG level
+ logger.info("addRequest lost data because three retries was insufficient.");
}
/**
@@ -262,6 +273,11 @@ public Accumulator() {
this(RequestCounter.this.time.getMilliseconds(), 0, 0, 0, 0, 0, 0, 0, 0, 0);
}
+ /**
+ * This method resets startTimeMS.
+ *
+ * @return
+ */
public Accumulator newWithTotal() {
return new Accumulator(RequestCounter.this.time.getMilliseconds(),
0,
View
7 src/java/voldemort/store/stats/StoreStats.java
@@ -4,6 +4,8 @@
import java.util.EnumMap;
import java.util.Map;
+import org.apache.log4j.Logger;
+
/**
* Some convenient statistics to track about the store
*
@@ -14,6 +16,8 @@
private final StoreStats parent;
private final Map<Tracked, RequestCounter> counters;
+ private static final Logger logger = Logger.getLogger(StoreStats.class.getName());
+
public StoreStats() {
this(null);
}
@@ -29,6 +33,9 @@ public StoreStats(StoreStats parent) {
counters.put(tracked, new RequestCounter(300000, true));
}
this.parent = parent;
+
+ logger.info("Constructed StoreStats object (" + System.identityHashCode(this)
+ + ") with parent object(" + System.identityHashCode(parent) + ")");
}
/**
Please sign in to comment.
Something went wrong with that request. Please try again.