From b4994bbe34b7c3dc613faea27096c617002547f4 Mon Sep 17 00:00:00 2001 From: Jay J Wylie Date: Mon, 12 Nov 2012 13:36:46 -0800 Subject: [PATCH] Added INFO level messages to better understand statistics tracking (StoreStats, 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) --- src/java/log4j.properties | 1 + .../store/stats/ClientSocketStats.java | 9 ++++ src/java/voldemort/store/stats/Histogram.java | 5 +- .../voldemort/store/stats/RequestCounter.java | 46 +++++++++++++------ .../voldemort/store/stats/StoreStats.java | 7 +++ 5 files changed, 51 insertions(+), 17 deletions(-) diff --git a/src/java/log4j.properties b/src/java/log4j.properties index 9a16ef00d2..9402646332 100755 --- a/src/java/log4j.properties +++ b/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 diff --git a/src/java/voldemort/store/stats/ClientSocketStats.java b/src/java/voldemort/store/stats/ClientSocketStats.java index d9f7584ce6..e1509afaf6 100644 --- a/src/java/voldemort/store/stats/ClientSocketStats.java +++ b/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 @@ public class ClientSocketStats { 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 */ diff --git a/src/java/voldemort/store/stats/Histogram.java b/src/java/voldemort/store/stats/Histogram.java index ec398f63c9..9abc306504 100644 --- a/src/java/voldemort/store/stats/Histogram.java +++ b/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]++; diff --git a/src/java/voldemort/store/stats/RequestCounter.java b/src/java/voldemort/store/stats/RequestCounter.java index 4857589576..c96cd61e7b 100644 --- a/src/java/voldemort/store/stats/RequestCounter.java +++ b/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 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(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, diff --git a/src/java/voldemort/store/stats/StoreStats.java b/src/java/voldemort/store/stats/StoreStats.java index e6cf34c99b..369d769378 100644 --- a/src/java/voldemort/store/stats/StoreStats.java +++ b/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 @@ public class StoreStats { private final StoreStats parent; private final Map 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) + ")"); } /**