From e29b2228f99923d7a76726abb3b3c2832667fdf7 Mon Sep 17 00:00:00 2001 From: Jay J Wylie Date: Tue, 13 Nov 2012 16:16:38 -0800 Subject: [PATCH] Added INFO level messages to better understand the performance of per-request instrumentation. Expect to remove most of this after debugging. --- .../voldemort/store/stats/RequestCounter.java | 13 ++++++++++- .../utils/pool/KeyedResourcePool.java | 22 +++++++++---------- 2 files changed, 23 insertions(+), 12 deletions(-) diff --git a/src/java/voldemort/store/stats/RequestCounter.java b/src/java/voldemort/store/stats/RequestCounter.java index c96cd61e7b..9315abcb54 100644 --- a/src/java/voldemort/store/stats/RequestCounter.java +++ b/src/java/voldemort/store/stats/RequestCounter.java @@ -180,6 +180,10 @@ public void addRequest(long timeNS, long numEmptyResponses, long bytes, long getAllAggregatedCount) { + // TODO: Remove this instrumentation + final long infoCutoffNs = 100 * 1000; // 100 us cut off for INFO display + long startTimeNs = System.nanoTime(); + long timeMs = timeNS / Time.NS_PER_MS; if(this.useHistogram) { histogram.insert(timeMs); @@ -198,8 +202,15 @@ public void addRequest(long timeNS, oldv.getAllAggregatedCount + getAllAggregatedCount, getAllAggregatedCount > oldv.getAllMaxCount ? getAllAggregatedCount : oldv.getAllMaxCount); - if(values.compareAndSet(oldv, newv)) + if(values.compareAndSet(oldv, newv)) { + long durationNs = System.nanoTime() - startTimeNs; + if(durationNs > infoCutoffNs) { + logger.info("addRequest (histogram.insert and accumulator update) took more than " + + infoCutoffNs + " ns: " + durationNs + " ns."); + } + return; + } } // TODO: Make this DEBUG level logger.info("addRequest lost data because three retries was insufficient."); diff --git a/src/java/voldemort/utils/pool/KeyedResourcePool.java b/src/java/voldemort/utils/pool/KeyedResourcePool.java index 2ee7f30b5f..6a6000ccc2 100644 --- a/src/java/voldemort/utils/pool/KeyedResourcePool.java +++ b/src/java/voldemort/utils/pool/KeyedResourcePool.java @@ -448,20 +448,20 @@ public boolean attemptGrow(K key, ResourceFactory objectFactory) throw if(!nonBlockingPut(resource)) { this.size.decrementAndGet(); objectFactory.destroy(key, resource); - if (currentCreatesInFlight>0) { - logger.info("attemptGrow established new connection for key " - + key.toString() + " with " + currentCreatesInFlight - + " other connection establishments in flight." - + " And then promptly destroyed the new connection."); + if(currentCreatesInFlight > 0) { + logger.info("attemptGrow established new connection for key " + + key.toString() + " with " + currentCreatesInFlight + + " other connection establishments in flight." + + " And then promptly destroyed the new connection."); } return false; } - if (currentCreatesInFlight>0) { - logger.info("attemptGrow established new connection for key " - + key.toString() + " with " + currentCreatesInFlight - + " other connection establishments in flight." - + " After checking in to KeyedResourcePool, there are " - + queue.size() + " destinations checked in."); + if(currentCreatesInFlight > 0) { + logger.info("attemptGrow established new connection for key " + + key.toString() + " with " + currentCreatesInFlight + + " other connection establishments in flight." + + " After checking in to KeyedResourcePool, there are " + + queue.size() + " destinations checked in."); } } } catch(Exception e) {