Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with HTTPS or Subversion.

Download ZIP

Loading…

Improve debug messages in Voldemort #89

Merged
merged 1 commit into from

2 participants

@pbailis

This patch improves the debugging messages introduced by commit fa3d6f6 in two ways:
1.) Print out hex representation of keys and values instead of current array format ("[48, 49, 79]").
2.) In tracing the stack traces, use the inputStream instead of the request handler; because the streamRequestHandler is used between requests, so using its identityHashCode causes collisions. Each DataInputStream is unique between requests, so we now use it instead.

@zhongjiewu zhongjiewu merged commit c8dcd82 into from
@zhongjiewu
Collaborator

Hi Peter,
The hudson is failing for Hinted Handoff test all the time. This test may fail from time to time but not all the time usually. I need to roll it back and test it locally before putting your changes back again. Did you remember if tests with debug on and off both passes?

@zhongjiewu zhongjiewu was assigned
@pbailis

IIRC, junit-long passed on my local machine.

Which test is the one that's failing? I just reran ant junit-test -Dtest.name=voldemort.store.routed.HintedHandoffTest on my local box with DEBUG statements both enabled and disabled and it passes in both cases.

@zhongjiewu
Collaborator

on Hudson, Job 74,75,76 that is tested after the merge is failing. I reverted it for now to prevent blocking the trunk. I think we should work on a branch and run more hudson jobs on the branch to make sure things work. I think I will probably see that same result if I run these two tests. I admit that this test is very funky.
My hypothesis is that your extra code is changing the time of how the test runs and make the failing condition reproduce every time it runs.

@zhongjiewu
Collaborator
@pbailis

I'm not able to repro this on my local machine.

The failure message doesn't seem related to my changes:
data should be stored in the slop for key = [7, -62, -7, 23, 118, 126, -103, -120, -31, 77, -36, 51, -72, 52, -98, -89, 32, -91, -92, 115, -6, 79, 73, -70, 119, -35, -61, -24, 80, -21, 22, -2]
(from http://test.project-voldemort.com:8080/job/voldemort-master/76/)

It's possible this is a timing issue. I'm curious if you can reproduce on your local machine with ant junit-test -Dtest.name=voldemort.store.routed.HintedHandoffTest

@zhongjiewu
Collaborator

I could reproduce it on my machine, both alone and inside junit.
However it does not fail every time.
This test uses src/java/voldemort/store/routed/action/ files, which some of your changes touch.
I am occupied by a prod-related feature change so I will try to see if such failure can be explained with the old explanation.

@zhongjiewu
Collaborator

I meant it does not fail every time when run alone. But never passed in "junit" task

@zhongjiewu
Collaborator

OK, the whole junit is also kind of unstable in results.

@pbailis

Zhongjie--did we figure this out?

@zhongjiewu
Collaborator

I need to pull it and run on eclipse myself and see what problem it is.

@zhongjiewu
Collaborator

Hi Peter, can you configure your Hudson job to run test on your branch that you want to pull? If that passes, then things will be a little weird.

@zhongjiewu
Collaborator

Interesting. I saw successful Hudson build for your branch.

@zhongjiewu
Collaborator

Your repo is behind quite a few commits as far as I can see. This could be why test results are not consistent.
Can you do a rebase from voldemort master? Don't include my revert. Make sure your pull request part does not get reverted and disappeared.

@pbailis

I'll do this tomorrow, though the fact that my Hudson job passed hints that this isn't a(n immediate) problem with my pull request.

@zhongjiewu
Collaborator

I have a theory.
So your changes in the HintedHandOff is exposing the test bug. I run the tests that excludes your change in HintedHandOff and it works fine.
So I will take a look at why your change is making that test fail everytime.
Though I know that this is not your fault.

@zhongjiewu
Collaborator

Hey Peter, is the logging changes in HintedHandoff Important for you?
We can try commiting everything except that file and see if the tests passes.

@pbailis

We can roll back the HintedHandoff changes--it's just for prettyprinting the key names.

@zhongjiewu
Collaborator

Just let you know, I have put your changes back. They are now in the master(except Hinted handoff file) and has been passing tests.
I am doing a release and they will be release in a week at most(hopefully done today).

@pbailis

Awesome--thanks! I'm now back in the country and should be faster to reply.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Commits on Aug 9, 2012
  1. @pbailis
This page is out of date. Refresh to see the latest.
View
11 src/java/voldemort/server/niosocket/AsyncRequestHandler.java
@@ -127,13 +127,16 @@ protected void read(SelectionKey selectionKey) throws IOException {
if(logger.isTraceEnabled())
logger.trace("Starting execution for " + socketChannel.socket());
- streamRequestHandler = requestHandler.handleRequest(new DataInputStream(inputStream),
- new DataOutputStream(outputStream));
+ DataInputStream dataInputStream = new DataInputStream(inputStream);
+ DataOutputStream dataOutputStream = new DataOutputStream(outputStream);
+
+ streamRequestHandler = requestHandler.handleRequest(dataInputStream,
+ dataOutputStream);
if(logger.isDebugEnabled()) {
logger.debug("AsyncRequestHandler:read finished request from "
+ socketChannel.socket().getRemoteSocketAddress() + " handlerRef: "
- + System.identityHashCode(streamRequestHandler) + " at time: "
+ + System.identityHashCode(dataInputStream) + " at time: "
+ System.currentTimeMillis() + " elapsed time: "
+ (System.nanoTime() - startNs) + " ns");
}
@@ -307,7 +310,7 @@ private StreamRequestHandlerState handleStreamRequestInternal(SelectionKey selec
if(logger.isDebugEnabled()) {
logger.debug("Handled request from "
+ socketChannel.socket().getRemoteSocketAddress() + " handlerRef: "
- + System.identityHashCode(streamRequestHandler) + " at time: "
+ + System.identityHashCode(dataInputStream) + " at time: "
+ System.currentTimeMillis() + " elapsed time: "
+ (System.nanoTime() - startNs) + " ns");
}
View
34 src/java/voldemort/server/protocol/vold/VoldemortNativeRequestHandler.java
@@ -135,7 +135,8 @@ private void handleGetVersion(DataInputStream inputStream,
if(logger.isDebugEnabled()) {
logger.debug("GETVERSIONS started at: " + startTimeMs + " handlerRef: "
- + System.identityHashCode(this) + " key: " + key + " "
+ + System.identityHashCode(inputStream) + " key: "
+ + ByteUtils.toHexString(key.get()) + " "
+ (System.nanoTime() - startTimeNs) + " ns, keySize: " + key.length()
+ "clocks: " + clockStr);
}
@@ -317,7 +318,7 @@ private void handleGet(DataInputStream inputStream,
}
writeResults(outputStream, results);
if(logger.isDebugEnabled()) {
- debugLogReturnValue(key, results, startTimeMs, startTimeNs, "GET");
+ debugLogReturnValue(inputStream, key, results, startTimeMs, startTimeNs, "GET");
}
}
@@ -374,7 +375,8 @@ private void handleGetAll(DataInputStream inputStream,
writeResults(outputStream, entry.getValue());
if(logger.isDebugEnabled()) {
- debugLogReturnValue(entry.getKey(),
+ debugLogReturnValue(inputStream,
+ entry.getKey(),
entry.getValue(),
startTimeMs,
startTimeNs,
@@ -386,7 +388,8 @@ private void handleGetAll(DataInputStream inputStream,
logger.debug("GETALL end");
}
- private void debugLogReturnValue(ByteArray key,
+ private void debugLogReturnValue(DataInputStream input,
+ ByteArray key,
List<Versioned<byte[]>> values,
long startTimeMs,
long startTimeNs,
@@ -406,12 +409,13 @@ private void debugLogReturnValue(ByteArray key,
valueHashStr += "]";
versionsStr += "]";
- logger.debug(getType + " handlerRef: " + System.identityHashCode(this) + " start time: "
- + startTimeMs + " key: " + key + " elapsed time: "
- + (System.nanoTime() - startTimeNs) + " ns, keySize: " + key.length()
- + " numResults: " + values.size() + " totalResultSize: " + totalValueSize
- + " resultSizes: " + valueSizeStr + " resultHashes: " + valueHashStr
- + " versions: " + versionsStr + " current time: " + System.currentTimeMillis());
+ logger.debug(getType + " handlerRef: " + System.identityHashCode(input) + " start time: "
+ + startTimeMs + " key: " + ByteUtils.toHexString(key.get())
+ + " elapsed time: " + (System.nanoTime() - startTimeNs) + " ns, keySize: "
+ + key.length() + " numResults: " + values.size() + " totalResultSize: "
+ + totalValueSize + " resultSizes: " + valueSizeStr + " resultHashes: "
+ + valueHashStr + " versions: " + versionsStr + " current time: "
+ + System.currentTimeMillis());
}
private void handlePut(DataInputStream inputStream,
@@ -447,9 +451,10 @@ private void handlePut(DataInputStream inputStream,
if(logger.isDebugEnabled()) {
logger.debug("PUT started at: " + startTimeMs + " handlerRef: "
- + System.identityHashCode(this) + " key: " + key + " "
+ + System.identityHashCode(inputStream) + " key: "
+ + ByteUtils.toHexString(key.get()) + " "
+ (System.nanoTime() - startTimeNs) + " ns, keySize: " + key.length()
- + " valueHash: " + value.hashCode() + " valueSize: " + valueSize
+ + " valueHash: " + value.hashCode() + " valueSize: " + value.length
+ " clockSize: " + clock.sizeInBytes() + " time: "
+ System.currentTimeMillis());
}
@@ -480,8 +485,9 @@ private void handleDelete(DataInputStream inputStream,
}
if(logger.isDebugEnabled()) {
- logger.debug("DELETE started at: " + startTimeMs + " key: " + key + " handlerRef: "
- + System.identityHashCode(this) + " time: "
+ logger.debug("DELETE started at: " + startTimeMs + " key: "
+ + ByteUtils.toHexString(key.get()) + " handlerRef: "
+ + System.identityHashCode(inputStream) + " time: "
+ (System.nanoTime() - startTimeNs) + " ns, keySize: " + key.length()
+ " clockSize: " + version.sizeInBytes());
}
View
10 src/java/voldemort/store/bdb/BdbStorageEngine.java
@@ -281,7 +281,7 @@ private Database getBdbDatabase() {
for(ByteArray key: keys) {
if(logger.isTraceEnabled())
- keyStr += key + " ";
+ keyStr += ByteUtils.toHexString(key.get()) + " ";
List<Versioned<byte[]>> values = get(cursor, key, readLockMode, versionedSerializer);
if(!values.isEmpty())
@@ -324,7 +324,7 @@ private Database getBdbDatabase() {
}
if(logger.isTraceEnabled()) {
- logger.trace("Completed GET from key " + key + " in "
+ logger.trace("Completed GET from key " + ByteUtils.toHexString(key.get()) + " in "
+ (System.nanoTime() - startTimeNs) + " ns at "
+ System.currentTimeMillis());
}
@@ -390,7 +390,7 @@ else if(occurred == Occurred.AFTER)
}
if(logger.isTraceEnabled()) {
- logger.trace("Completed PUT to key " + key + " (keyRef: "
+ logger.trace("Completed PUT to key " + ByteUtils.toHexString(key.get()) + " (keyRef: "
+ System.identityHashCode(key) + " value " + value + " in "
+ (System.nanoTime() - startTimeNs) + " ns at "
+ System.currentTimeMillis());
@@ -431,8 +431,8 @@ public boolean delete(ByteArray key, Version version) throws PersistenceFailureE
} finally {
if(logger.isTraceEnabled()) {
- logger.trace("Completed DELETE of key " + key + " (keyRef: "
- + System.identityHashCode(key) + ") in "
+ logger.trace("Completed DELETE of key " + ByteUtils.toHexString(key.get())
+ + " (keyRef: " + System.identityHashCode(key) + ") in "
+ (System.nanoTime() - startTimeNs) + " ns at "
+ System.currentTimeMillis());
}
View
45 src/java/voldemort/store/routed/PipelineRoutedStore.java
@@ -251,9 +251,10 @@ public PipelineRoutedStore(String name,
}
if(logger.isDebugEnabled()) {
- logger.debug("Finished " + pipeline.getOperation().getSimpleName() + " for key " + key
- + " keyRef: " + System.identityHashCode(key) + "; started at "
- + startTimeMs + " took " + (System.nanoTime() - startTimeNs) + " values: "
+ logger.debug("Finished " + pipeline.getOperation().getSimpleName() + " for key "
+ + ByteUtils.toHexString(key.get()) + " keyRef: "
+ + System.identityHashCode(key) + "; started at " + startTimeMs + " took "
+ + (System.nanoTime() - startTimeNs) + " values: "
+ formatNodeValuesFromGet(pipelineData.getResponses()));
}
@@ -355,9 +356,10 @@ private String formatNodeValuesFromGet(List<Response<ByteArray, List<Versioned<b
throw pipelineData.getFatalError();
if(logger.isDebugEnabled()) {
- logger.debug("Finished " + pipeline.getOperation().getSimpleName() + "for keys " + keys
- + " keyRef: " + System.identityHashCode(keys) + "; started at "
- + startTimeMs + " took " + (System.nanoTime() - startTimeNs) + " values: "
+ logger.debug("Finished " + pipeline.getOperation().getSimpleName() + "for keys "
+ + ByteArray.toHexStrings(keys) + " keyRef: "
+ + System.identityHashCode(keys) + "; started at " + startTimeMs + " took "
+ + (System.nanoTime() - startTimeNs) + " values: "
+ formatNodeValuesFromGetAll(pipelineData.getResponses()));
}
@@ -369,8 +371,9 @@ private String formatNodeValuesFromGetAll(List<Response<Iterable<ByteArray>, Map
StringBuilder builder = new StringBuilder();
builder.append("{");
for(Response<Iterable<ByteArray>, Map<ByteArray, List<Versioned<byte[]>>>> r: list) {
- builder.append("(nodeId=" + r.getNode().getId() + ", key=" + r.getKey()
- + ", retrieved= " + r.getValue() + ")");
+ builder.append("(nodeId=" + r.getNode().getId() + ", keys="
+ + ByteArray.toHexStrings(r.getKey()) + ", retrieved= " + r.getValue()
+ + ")");
builder.append(", ");
}
builder.append("}");
@@ -469,9 +472,10 @@ private String formatNodeValuesFromGetAll(List<Response<Iterable<ByteArray>, Map
results.addAll(response.getValue());
if(logger.isDebugEnabled()) {
- logger.debug("Finished " + pipeline.getOperation().getSimpleName() + " for key " + key
- + " keyRef: " + System.identityHashCode(key) + "; started at "
- + startTimeMs + " took " + (System.nanoTime() - startTimeNs) + " values: "
+ logger.debug("Finished " + pipeline.getOperation().getSimpleName() + " for key "
+ + ByteUtils.toHexString(key.get()) + " keyRef: "
+ + System.identityHashCode(key) + "; started at " + startTimeMs + " took "
+ + (System.nanoTime() - startTimeNs) + " values: "
+ formatNodeValuesFromGetVersions(pipelineData.getResponses()));
}
@@ -483,8 +487,9 @@ private String formatNodeValuesFromGetAll(List<Response<Iterable<ByteArray>, Map
StringBuilder builder = new StringBuilder();
builder.append("{");
for(Response<ByteArray, List<Version>> r: results) {
- builder.append("(nodeId=" + r.getNode().getId() + ", key=" + r.getKey()
- + ", retrieved= " + r.getValue() + "), ");
+ builder.append("(nodeId=" + r.getNode().getId() + ", key="
+ + ByteUtils.toHexString(r.getKey().get()) + ", retrieved= "
+ + r.getValue() + "), ");
}
builder.append("}");
@@ -575,8 +580,9 @@ public boolean delete(final ByteArray key, final Version version) throws Voldemo
if(logger.isDebugEnabled()) {
logger.debug("Finished " + pipeline.getOperation().getSimpleName() + " for key "
- + key.get() + " keyRef: " + System.identityHashCode(key) + "; started at "
- + startTimeMs + " took " + (System.nanoTime() - startTimeNs));
+ + ByteUtils.toHexString(key.get()) + " keyRef: "
+ + System.identityHashCode(key) + "; started at " + startTimeMs + " took "
+ + (System.nanoTime() - startTimeNs));
}
if(pipelineData.getFatalError() != null)
@@ -700,10 +706,11 @@ public void put(ByteArray key, Versioned<byte[]> versioned, byte[] transforms)
}
if(logger.isDebugEnabled()) {
- logger.debug("Finished " + pipeline.getOperation().getSimpleName() + " for key " + key
- + " keyRef: " + System.identityHashCode(key) + "; started at "
- + startTimeMs + " took " + (System.nanoTime() - startTimeNs) + " value: "
- + versioned.getValue() + " (size: " + versioned.getValue().length + ")");
+ logger.debug("Finished " + pipeline.getOperation().getSimpleName() + " for key "
+ + ByteUtils.toHexString(key.get()) + " keyRef: "
+ + System.identityHashCode(key) + "; started at " + startTimeMs + " took "
+ + (System.nanoTime() - startTimeNs) + " value: " + versioned.getValue()
+ + " (size: " + versioned.getValue().length + ")");
}
if(pipelineData.getFatalError() != null)
View
11 src/java/voldemort/store/routed/action/AbstractReadRepair.java
@@ -24,10 +24,11 @@
import voldemort.store.nonblockingstore.NonblockingStore;
import voldemort.store.routed.NodeValue;
import voldemort.store.routed.Pipeline;
+import voldemort.store.routed.Pipeline.Event;
import voldemort.store.routed.PipelineData;
import voldemort.store.routed.ReadRepairer;
-import voldemort.store.routed.Pipeline.Event;
import voldemort.utils.ByteArray;
+import voldemort.utils.ByteUtils;
import voldemort.versioning.VectorClock;
import voldemort.versioning.Versioned;
@@ -101,7 +102,8 @@ public void execute(Pipeline pipeline) {
try {
if(logger.isDebugEnabled())
logger.debug("Doing read repair on node " + v.getNodeId() + " for key '"
- + v.getKey() + "' with version " + v.getVersion() + ".");
+ + ByteUtils.toHexString(v.getKey().get()) + "' with version "
+ + v.getVersion() + ".");
NonblockingStore store = nonblockingStores.get(v.getNodeId());
store.submitPutRequest(v.getKey(), v.getVersioned(), null, null, timeoutMs);
@@ -110,8 +112,9 @@ public void execute(Pipeline pipeline) {
logger.debug("Read repair cancelled due to application level exception on node "
+ v.getNodeId()
+ " for key '"
- + v.getKey()
- + "' with version " + v.getVersion() + ": " + e.getMessage());
+ + ByteUtils.toHexString(v.getKey().get())
+ + "' with version "
+ + v.getVersion() + ": " + e.getMessage());
} catch(Exception e) {
logger.debug("Read repair failed: ", e);
}
View
6 src/java/voldemort/store/routed/action/PerformParallelDeleteRequests.java
@@ -93,9 +93,9 @@ public void execute(final Pipeline pipeline) {
public void requestComplete(Object result, long requestTime) {
if(logger.isTraceEnabled())
- logger.info(pipeline.getOperation().getSimpleName()
- + " response received (" + requestTime + " ms.) from node "
- + node.getId());
+ logger.trace(pipeline.getOperation().getSimpleName()
+ + " response received (" + requestTime + " ms.) from node "
+ + node.getId());
Response<ByteArray, Object> response = new Response<ByteArray, Object>(node,
key,
View
4 src/java/voldemort/store/routed/action/PerformParallelPutRequests.java
@@ -42,6 +42,7 @@
import voldemort.store.slop.HintedHandoff;
import voldemort.store.slop.Slop;
import voldemort.utils.ByteArray;
+import voldemort.utils.ByteUtils;
import voldemort.utils.Time;
import voldemort.versioning.ObsoleteVersionException;
import voldemort.versioning.Versioned;
@@ -130,7 +131,8 @@ public void requestComplete(Object result, long requestTime) {
responses.put(node.getId(), response);
if(logger.isDebugEnabled())
- logger.debug("Finished secondary PUT for key " + key + " (keyRef: "
+ logger.debug("Finished secondary PUT for key "
+ + ByteUtils.toHexString(key.get()) + " (keyRef: "
+ System.identityHashCode(key) + "); took " + requestTime
+ " ms on node " + node.getId() + "(" + node.getHost() + ")");
View
16 src/java/voldemort/store/routed/action/PerformParallelRequests.java
@@ -38,6 +38,7 @@
import voldemort.store.routed.Pipeline.Operation;
import voldemort.store.routed.Response;
import voldemort.utils.ByteArray;
+import voldemort.utils.ByteUtils;
import voldemort.utils.Utils;
public class PerformParallelRequests<V, PD extends BasicPipelineData<V>> extends
@@ -111,10 +112,10 @@ public void requestComplete(Object result, long requestTime) {
requestTime);
if(logger.isDebugEnabled())
logger.debug("Finished " + pipeline.getOperation().getSimpleName()
- + " for key " + key + " (keyRef: "
- + System.identityHashCode(key) + "); started at " + startMs
- + " took " + requestTime + " ms on node " + node.getId() + "("
- + node.getHost() + ")");
+ + " for key " + ByteUtils.toHexString(key.get())
+ + " (keyRef: " + System.identityHashCode(key)
+ + "); started at " + startMs + " took " + requestTime
+ + " ms on node " + node.getId() + "(" + node.getHost() + ")");
responses.put(node.getId(), response);
latch.countDown();
@@ -174,9 +175,10 @@ else if(pipeline.getOperation() == Operation.GET_VERSIONS)
}
if(logger.isDebugEnabled())
- logger.debug("GET for key " + key + " (keyRef: " + System.identityHashCode(key)
- + "); successes: " + pipelineData.getSuccesses() + " preferred: "
- + preferred + " required: " + required);
+ logger.debug("GET for key " + ByteUtils.toHexString(key.get()) + " (keyRef: "
+ + System.identityHashCode(key) + "); successes: "
+ + pipelineData.getSuccesses() + " preferred: " + preferred + " required: "
+ + required);
if(pipelineData.getSuccesses() < required) {
if(insufficientSuccessesEvent != null) {
View
19 src/java/voldemort/store/routed/action/PerformSerialGetAllRequests.java
@@ -79,10 +79,11 @@ public void execute(Pipeline pipeline) {
boolean zoneRequirement = false;
MutableInt successCount = pipelineData.getSuccessCount(key);
- if(logger.isDebugEnabled())
- logger.debug("GETALL for key " + key + " (keyRef: " + System.identityHashCode(key)
- + ") successes: " + successCount.intValue() + " preferred: " + preferred
- + " required: " + required);
+ if(logger.isDebugEnabled())
+ logger.debug("GETALL for key " + ByteUtils.toHexString(key.get()) + " (keyRef: "
+ + System.identityHashCode(key) + ") successes: "
+ + successCount.intValue() + " preferred: " + preferred + " required: "
+ + required);
if(successCount.intValue() >= preferred) {
if(pipelineData.getZonesRequired() != null) {
@@ -138,11 +139,11 @@ public void execute(Pipeline pipeline) {
failureDetector.recordSuccess(response.getNode(), response.getRequestTime());
if(logger.isDebugEnabled())
- logger.debug("GET for key " + key + " (keyRef: "
- + System.identityHashCode(key) + ") successes: "
- + successCount.intValue() + " preferred: " + preferred
- + " required: " + required + " new GET success on node "
- + node.getId());
+ logger.debug("GET for key " + ByteUtils.toHexString(key.get())
+ + " (keyRef: " + System.identityHashCode(key)
+ + ") successes: " + successCount.intValue() + " preferred: "
+ + preferred + " required: " + required
+ + " new GET success on node " + node.getId());
HashSet<Integer> zoneResponses = null;
if(pipelineData.getKeyToZoneResponse().containsKey(key)) {
View
12 src/java/voldemort/store/routed/action/PerformSerialPutRequests.java
@@ -29,6 +29,7 @@
import voldemort.store.routed.Pipeline.Event;
import voldemort.store.routed.PutPipelineData;
import voldemort.utils.ByteArray;
+import voldemort.utils.ByteUtils;
import voldemort.utils.Time;
import voldemort.versioning.VectorClock;
import voldemort.versioning.Versioned;
@@ -173,7 +174,8 @@ public void execute(Pipeline pipeline) {
} else {
if(logger.isDebugEnabled())
- logger.debug("Finished master PUT for key " + key + " (keyRef: "
+ logger.debug("Finished master PUT for key "
+ + ByteUtils.toHexString(key.get()) + " (keyRef: "
+ System.identityHashCode(key) + "); started at "
+ startMasterMs + " took "
+ (System.nanoTime() - startMasterNs) + " ns on node "
@@ -185,10 +187,10 @@ public void execute(Pipeline pipeline) {
}
} else {
if(logger.isDebugEnabled())
- logger.debug("Finished master PUT for key " + key + " (keyRef: "
- + System.identityHashCode(key) + "); started at " + startMasterMs
- + " took " + (System.nanoTime() - startMasterNs) + " ns on node "
- + (node == null ? "NULL" : node.getId()) + "("
+ logger.debug("Finished master PUT for key " + ByteUtils.toHexString(key.get())
+ + " (keyRef: " + System.identityHashCode(key) + "); started at "
+ + startMasterMs + " took " + (System.nanoTime() - startMasterNs)
+ + " ns on node " + (node == null ? "NULL" : node.getId()) + "("
+ (node == null ? "NULL" : node.getHost()) + ")");
pipeline.addEvent(masterDeterminedEvent);
View
8 src/java/voldemort/store/routed/action/PerformSerialRequests.java
@@ -31,6 +31,7 @@
import voldemort.store.routed.Pipeline.Event;
import voldemort.store.routed.Response;
import voldemort.utils.ByteArray;
+import voldemort.utils.ByteUtils;
import voldemort.utils.Time;
public class PerformSerialRequests<V, PD extends BasicPipelineData<V>> extends
@@ -99,9 +100,10 @@ public void execute(Pipeline pipeline) {
((System.nanoTime() - start) / Time.NS_PER_MS));
if(logger.isDebugEnabled())
- logger.debug(pipeline.getOperation().getSimpleName() + " for key " + key
- + " successes: " + pipelineData.getSuccesses() + " preferred: "
- + preferred + " required: " + required + " new "
+ logger.debug(pipeline.getOperation().getSimpleName() + " for key "
+ + ByteUtils.toHexString(key.get()) + " successes: "
+ + pipelineData.getSuccesses() + " preferred: " + preferred
+ + " required: " + required + " new "
+ pipeline.getOperation().getSimpleName() + " success on node "
+ node.getId());
View
60 src/java/voldemort/store/slop/HintedHandoff.java
@@ -27,11 +27,12 @@
import voldemort.serialization.SlopSerializer;
import voldemort.store.Store;
import voldemort.store.UnreachableStoreException;
-import voldemort.store.slop.strategy.HintedHandoffStrategy;
import voldemort.store.nonblockingstore.NonblockingStore;
import voldemort.store.nonblockingstore.NonblockingStoreCallback;
import voldemort.store.routed.Response;
+import voldemort.store.slop.strategy.HintedHandoffStrategy;
import voldemort.utils.ByteArray;
+import voldemort.utils.ByteUtils;
import voldemort.utils.Time;
import voldemort.utils.Utils;
import voldemort.versioning.ObsoleteVersionException;
@@ -67,7 +68,8 @@
* Create a Hinted Handoff object
*
* @param failureDetector The failure detector
- * @param nonblockingSlopStores A map of node ids to nonb-locking slop stores
+ * @param nonblockingSlopStores A map of node ids to nonb-locking slop
+ * stores
* @param slopStores A map of node ids to blocking slop stores
* @param handoffStrategy The {@link HintedHandoffStrategy} implementation
* @param failedNodes A list of nodes in the original preflist for the
@@ -89,15 +91,18 @@ public HintedHandoff(FailureDetector failureDetector,
}
/**
- * Like {@link #sendHintSerial(voldemort.cluster.Node, voldemort.versioning.Version, Slop)},
- * but doesn't block the pipeline. Intended for handling prolonged failures without
- * incurring a performance cost.
- *
- * @see #sendHintSerial(voldemort.cluster.Node, voldemort.versioning.Version, Slop)
+ * Like
+ * {@link #sendHintSerial(voldemort.cluster.Node, voldemort.versioning.Version, Slop)}
+ * , but doesn't block the pipeline. Intended for handling prolonged
+ * failures without incurring a performance cost.
+ *
+ * @see #sendHintSerial(voldemort.cluster.Node,
+ * voldemort.versioning.Version, Slop)
*/
public void sendHintParallel(final Node failedNode, final Version version, final Slop slop) {
final ByteArray slopKey = slop.makeKey();
- Versioned<byte[]> slopVersioned = new Versioned<byte[]>(slopSerializer.toBytes(slop), version);
+ Versioned<byte[]> slopVersioned = new Versioned<byte[]>(slopSerializer.toBytes(slop),
+ version);
for(final Node node: handoffStrategy.routeHint(failedNode)) {
int nodeId = node.getId();
@@ -111,10 +116,12 @@ public void sendHintParallel(final Node failedNode, final Version version, final
final long startNs = System.nanoTime();
if(logger.isDebugEnabled())
- logger.debug("Slop attempt to write " + slop.getKey() + " for " + failedNode
- + " to node " + node);
+ logger.debug("Slop attempt to write "
+ + ByteUtils.toHexString(slop.getKey().get()) + " for "
+ + failedNode + " to node " + node);
NonblockingStoreCallback callback = new NonblockingStoreCallback() {
+
public void requestComplete(Object result, long requestTime) {
Response<ByteArray, Object> response = new Response<ByteArray, Object>(node,
slopKey,
@@ -130,15 +137,16 @@ public void requestComplete(Object result, long requestTime) {
if(response.getValue() instanceof UnreachableStoreException) {
UnreachableStoreException use = (UnreachableStoreException) response.getValue();
- if(logger.isDebugEnabled())
- logger.debug("Write of key " + slop.getKey() + " for "
- + failedNode + " to node " + node
- + " failed due to unreachable: "
- + use.getMessage());
+ if(logger.isDebugEnabled())
+ logger.debug("Write of key "
+ + ByteUtils.toHexString(slop.getKey().get())
+ + " for " + failedNode + " to node " + node
+ + " failed due to unreachable: "
+ + use.getMessage());
failureDetector.recordException(node,
(System.nanoTime() - startNs)
- / Time.NS_PER_MS,
+ / Time.NS_PER_MS,
use);
}
sendHintSerial(failedNode, version, slop);
@@ -147,7 +155,8 @@ public void requestComplete(Object result, long requestTime) {
}
if(logger.isDebugEnabled())
- logger.debug("Slop write of key " + slop.getKey() + " for "
+ logger.debug("Slop write of key "
+ + ByteUtils.toHexString(slop.getKey().get()) + " for "
+ failedNode + " to node " + node + " succeeded in "
+ (System.nanoTime() - startNs) + " ns");
@@ -157,16 +166,12 @@ public void requestComplete(Object result, long requestTime) {
}
};
- nonblockingStore.submitPutRequest(slopKey,
- slopVersioned,
- null,
- callback,
- timeoutMs);
+ nonblockingStore.submitPutRequest(slopKey, slopVersioned, null, callback, timeoutMs);
break;
}
}
}
-
+
/**
* Send a hint of a request originally meant for the failed node to another
* node in the ring, as selected by the {@link HintedHandoffStrategy}
@@ -191,7 +196,8 @@ public boolean sendHintSerial(Node failedNode, Version version, Slop slop) {
try {
if(logger.isDebugEnabled())
- logger.debug("Slop attempt to write " + slop.getKey() + " (keyRef: "
+ logger.debug("Slop attempt to write "
+ + ByteUtils.toHexString(slop.getKey().get()) + " (keyRef: "
+ System.identityHashCode(slop.getKey()) + ") for "
+ failedNode + " to node " + node);
@@ -214,9 +220,9 @@ public boolean sendHintSerial(Node failedNode, Version version, Slop slop) {
}
if(logger.isDebugEnabled())
- logger.debug("Slop write of key " + slop.getKey() + " (keyRef: "
- + System.identityHashCode(slop.getKey()) + " for " + failedNode
- + " to node " + node + " succeeded in "
+ logger.debug("Slop write of key " + ByteUtils.toHexString(slop.getKey().get())
+ + " (keyRef: " + System.identityHashCode(slop.getKey()) + " for "
+ + failedNode + " to node " + node + " succeeded in "
+ (System.nanoTime() - startNs) + " ns");
}
}
View
14 src/java/voldemort/utils/ByteArray.java
@@ -1,6 +1,7 @@
package voldemort.utils;
import java.io.Serializable;
+import java.util.ArrayList;
import java.util.Arrays;
/**
@@ -43,6 +44,19 @@ public String toString() {
return Arrays.toString(underlying);
}
+ /**
+ * Translate the each ByteArray in an iterable into a hexidecimal string
+ *
+ * @param arrays The array of bytes to translate
+ * @return An iterable of converted strings
+ */
+ public static Iterable<String> toHexStrings(Iterable<ByteArray> arrays) {
+ ArrayList<String> ret = new ArrayList<String>();
+ for(ByteArray array: arrays)
+ ret.add(ByteUtils.toHexString(array.get()));
+ return ret;
+ }
+
public int length() {
return underlying.length;
}
Something went wrong with that request. Please try again.