Skip to content

Commit

Permalink
Clean up INFO debugging messages to be DEBUG. Minor other clean up too.
Browse files Browse the repository at this point in the history
  • Loading branch information
@jayjwylie
jayjwylie committed Jan 15, 2013
1 parent e29b222 commit 03214c9
Show file tree
Hide file tree
Showing 7 changed files with 83 additions and 76 deletions.
34 changes: 13 additions & 21 deletions src/java/voldemort/store/socket/clientrequest/ClientRequestExecutorFactory.java
View file
Expand Up @@ -133,21 +133,21 @@ public ClientRequestExecutor create(SocketDestination dest) throws Exception {
socketChannel.configureBlocking(false);
socketChannel.connect(new InetSocketAddress(dest.getHost(), dest.getPort()));

long startTime = System.currentTimeMillis();
long duration = 0;
long currWaitTime = 1;
long prevWaitTime = 1;
long startTimeMs = System.currentTimeMillis();
long durationMs = 0;
long currWaitTimeMs = 1;
long prevWaitTimeMS = 1;

// Since we're non-blocking and it takes a non-zero amount of time
// to connect, invoke finishConnect and loop.
while(!socketChannel.finishConnect()) {
duration = System.currentTimeMillis() - startTime;
long remaining = this.connectTimeoutMs - duration;
durationMs = System.currentTimeMillis() - startTimeMs;
long remaining = this.connectTimeoutMs - durationMs;

if(remaining < 0) {
throw new ConnectException("Cannot connect socket " + numCreated + " for "
+ dest.getHost() + ":" + dest.getPort() + " after "
+ duration + " ms");
+ durationMs + " ms");
}

if(logger.isTraceEnabled())
Expand All @@ -158,28 +158,20 @@ public ClientRequestExecutor create(SocketDestination dest) throws Exception {
try {
// Break up the connection timeout into smaller units,
// employing a Fibonacci-style back-off (1, 2, 3, 5, 8, ...)
Thread.sleep(Math.min(remaining, currWaitTime));
currWaitTime = Math.min(currWaitTime + prevWaitTime, 50);
prevWaitTime = currWaitTime - prevWaitTime;
Thread.sleep(Math.min(remaining, currWaitTimeMs));
currWaitTimeMs = Math.min(currWaitTimeMs + prevWaitTimeMS, 50);
prevWaitTimeMS = currWaitTimeMs - prevWaitTimeMS;
} catch(InterruptedException e) {
if(logger.isEnabledFor(Level.WARN))
logger.warn(e, e);
}
}
duration = System.currentTimeMillis() - startTime;

if(duration > 0) {
if(logger.isInfoEnabled()) {
logger.info("Created socket " + numCreated + " for " + dest.getHost() + ":"
+ dest.getPort() + " using protocol "
+ dest.getRequestFormatType().getCode() + " after " + duration
+ " ms.");
}
}
durationMs = System.currentTimeMillis() - startTimeMs;

if(logger.isDebugEnabled())
logger.debug("Created socket " + numCreated + " for " + dest.getHost() + ":"
+ dest.getPort() + " using protocol "
+ dest.getRequestFormatType().getCode() + " after " + duration
+ dest.getRequestFormatType().getCode() + " after " + durationMs
+ " ms.");

// check buffer sizes--you often don't get out what you put in!
Expand Down
12 changes: 8 additions & 4 deletions src/java/voldemort/store/socket/clientrequest/ClientRequestExecutorPool.java
View file
Expand Up @@ -156,8 +156,12 @@ public SocketStore create(String storeName,
*/

public ClientRequestExecutor checkout(SocketDestination destination) {
// time checkout
long start = System.nanoTime();
// timing instrumentation (stats only)
long startTimeNs = 0;
if(stats != null) {
startTimeNs = System.nanoTime();
}

ClientRequestExecutor clientRequestExecutor;
try {
clientRequestExecutor = queuedPool.checkout(destination);
Expand All @@ -172,9 +176,9 @@ public ClientRequestExecutor checkout(SocketDestination destination) {
throw new UnreachableStoreException("Failure while checking out socket for "
+ destination + ": ", e);
} finally {
long end = System.nanoTime();
if(stats != null) {
stats.recordCheckoutTimeUs(destination, (end - start) / Time.NS_PER_US);
stats.recordCheckoutTimeUs(destination, (System.nanoTime() - startTimeNs)
/ Time.NS_PER_US);
stats.recordCheckoutQueueLength(destination,
queuedPool.getBlockingGetsCount(destination));
}
Expand Down
23 changes: 15 additions & 8 deletions src/java/voldemort/store/stats/ClientSocketStats.java
View file
Expand Up @@ -95,8 +95,8 @@ public ClientSocketStats(ClientSocketStats parent,
this.pool = pool;
this.jmxId = jmxId;

logger.info("Constructed ClientSocketStatsStats object (" + System.identityHashCode(this)
+ ") with parent object(" + System.identityHashCode(parent) + ")");
logger.debug("Constructed ClientSocketStatsStats object (" + System.identityHashCode(this)
+ ") with parent object(" + System.identityHashCode(parent) + ")");
}

/**
Expand All @@ -111,8 +111,8 @@ public ClientSocketStats(int jmxId) {
this.pool = null;
this.jmxId = jmxId;

logger.info("Constructed ClientSocketStatsStats object (" + System.identityHashCode(this)
+ ") with parent object(" + System.identityHashCode(parent) + ")");
logger.debug("Constructed ClientSocketStatsStats object (" + System.identityHashCode(this)
+ ") with parent object(" + System.identityHashCode(parent) + ")");
}

/* get per node stats, create one if not exist */
Expand Down Expand Up @@ -324,7 +324,11 @@ protected void checkMonitoringInterval() {
if(parent == null && statsMap != null) {
int monitoringInterval = this.monitoringInterval.get();
if(monitoringCount % (monitoringInterval + 1) == monitoringInterval) {
long startTimeNs = System.nanoTime();
// timing instrumentation (debug only)
long startTimeNs = 0;
if(logger.isDebugEnabled()) {
startTimeNs = System.nanoTime();
}

// reset all children
Iterator<SocketDestination> it = statsMap.keySet().iterator();
Expand All @@ -335,9 +339,12 @@ protected void checkMonitoringInterval() {
// reset itself
resetForInterval();

logger.info("ClientSocketStats(" + System.identityHashCode(this)
+ ")::checkMonitoringInterval: reset self and all children in "
+ (startTimeNs - System.nanoTime()) + " ns.");
// timing instrumentation (debug only)
if(logger.isDebugEnabled()) {
logger.debug("ClientSocketStats(" + System.identityHashCode(this)
+ ")::checkMonitoringInterval: reset self and all children in "
+ (System.nanoTime() - startTimeNs) + " ns.");
}
}
}
}
Expand Down
8 changes: 5 additions & 3 deletions src/java/voldemort/store/stats/Histogram.java
View file
Expand Up @@ -52,12 +52,13 @@ 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;
this.buckets = new int[nBuckets];
reset();

logger.debug("Constructed a histogram with " + nBuckets + " buckets.");
}

/**
Expand Down Expand Up @@ -89,7 +90,8 @@ public synchronized void insert(long data) {
index = data / step;
}
if(index < 0 || index >= nBuckets) {
// This is dead code. Defend against code changes in future.
// This should be dead code. Defending against code changes in
// future.
logger.error(data + " can't be bucketed because index is not in range [0,nBuckets).");
return;
}
Expand All @@ -100,7 +102,7 @@ public synchronized void insert(long data) {

/**
* Find the a value <em>n</em> such that the percentile falls within [
* <em>n</em>, <em>n + step</em>). This method does a <em>LINEAR</em> prove
* <em>n</em>, <em>n + step</em>). This method does a <em>LINEAR</em> probe
* of the histogram. I.e., this method is O(nBuckets).
*
* @param quantile The percentile to find
Expand Down
45 changes: 30 additions & 15 deletions src/java/voldemort/store/stats/RequestCounter.java
View file
Expand Up @@ -116,15 +116,23 @@ private void maybeResetHistogram() {
Accumulator accum = values.get();
long now = time.getMilliseconds();
if(now - accum.startTimeMS > durationMs) {
long startTimeNs = System.nanoTime();
// timing instrumentation (debug only)
long startTimeNs = 0;
if(logger.isDebugEnabled()) {
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.");

// timing instrumentation (debug only)
if(logger.isDebugEnabled()) {
logger.debug("Histogram (" + System.identityHashCode(histogram)
+ ") : reset, Q95, & Q99 took " + (System.nanoTime() - startTimeNs)
+ " ns.");
}
}
}

Expand Down Expand Up @@ -180,9 +188,11 @@ 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();
// timing instrumentation (trace only)
long startTimeNs = 0;
if(logger.isTraceEnabled()) {
startTimeNs = System.nanoTime();
}

long timeMs = timeNS / Time.NS_PER_MS;
if(this.useHistogram) {
Expand All @@ -203,17 +213,22 @@ public void addRequest(long timeNS,
getAllAggregatedCount > oldv.getAllMaxCount ? getAllAggregatedCount
: oldv.getAllMaxCount);
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.");
// timing instrumentation (trace only)
if(logger.isTraceEnabled()) {
logger.trace("addRequest (histogram.insert and accumulator update) took "
+ (System.nanoTime() - startTimeNs) + " ns.");
}

// Return since data has been accumulated
return;
}
}
// TODO: Make this DEBUG level
logger.info("addRequest lost data because three retries was insufficient.");
logger.info("addRequest lost timing instrumentation data because three retries was insufficient to update the accumulator.");

// timing instrumentation (trace only)
if(logger.isTraceEnabled()) {
logger.trace("addRequest (histogram.insert and accumulator update) took "
+ (System.nanoTime() - startTimeNs) + " ns.");
}
}

/**
Expand Down
4 changes: 2 additions & 2 deletions src/java/voldemort/store/stats/StoreStats.java
View file
Expand Up @@ -34,8 +34,8 @@ public StoreStats(StoreStats parent) {
}
this.parent = parent;

logger.info("Constructed StoreStats object (" + System.identityHashCode(this)
+ ") with parent object(" + System.identityHashCode(parent) + ")");
logger.debug("Constructed StoreStats object (" + System.identityHashCode(this)
+ ") with parent object (" + System.identityHashCode(parent) + ")");
}

/**
Expand Down
33 changes: 10 additions & 23 deletions src/java/voldemort/utils/pool/KeyedResourcePool.java
View file
Expand Up @@ -237,8 +237,6 @@ public void checkin(K key, V resource) throws Exception {
}
}

// This method may be made protected in the future for the benefit of
// classes which extend from KeyedResourcePool.
protected boolean isOpenAndValid(K key, V resource) throws Exception {
if(isOpen.get() && objectFactory.validate(key, resource)) {
return true;
Expand Down Expand Up @@ -405,7 +403,6 @@ protected static class Pool<V> {

final private AtomicInteger size = new AtomicInteger(0);
final private AtomicInteger blockingGets = new AtomicInteger(0);
final private AtomicInteger createsInFlight = new AtomicInteger(0);
final private int maxPoolSize;
final private BlockingQueue<V> queue;

Expand Down Expand Up @@ -436,32 +433,22 @@ public <K> boolean attemptGrow(K key, ResourceFactory<K, V> objectFactory) throw

if(this.size.incrementAndGet() <= this.maxPoolSize) {
try {
V resource = null;
int currentCreatesInFlight = 0;
try {
currentCreatesInFlight = createsInFlight.getAndIncrement();
resource = objectFactory.create(key);
} finally {
createsInFlight.decrementAndGet();
}
V resource = objectFactory.create(key);
if(resource != null) {
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.");
}
logger.info("attemptGrow established new connection for key "
+ key.toString()
+ " and immediately destroyed the new connection "
+ "because there were too many connections already established.");
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(logger.isDebugEnabled()) {
logger.debug("attemptGrow established new connection for key "
+ key.toString() + ". "
+ " After checking in to KeyedResourcePool, there are "
+ queue.size() + " destinations checked in.");
}
}
} catch(Exception e) {
Expand Down

0 comments on commit 03214c9

Please sign in to comment.