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)

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

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 */

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]++;

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,

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<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) + ")");
     }
 
     /**