Skip to content

HDDS-3981. Add more debug level log to XceiverClientGrpc for debug purpose #1214

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
xiaoyuyao merged 8 commits into from
Sep 17, 2020
Merged

HDDS-3981. Add more debug level log to XceiverClientGrpc for debug purpose #1214

Changes from 6 commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
0729631
HDDS-3981. Add more debug level log to XceiverClientGrpc for debug pu…
maobaolong Jul 17, 2020
39a4825
trigger new ci check
maobaolong Jul 18, 2020
a49773e
trigger new ci check
maobaolong Jul 18, 2020
e1d7e9a
trigger new ci check
maobaolong Jul 18, 2020
9e13176
trigger new ci check
maobaolong Jul 22, 2020
6a3d7b3
trigger new ci check
maobaolong Jul 22, 2020
6a7a413
Address comments, log the ip address o dn only.
maobaolong Aug 10, 2020
0f027d8
Address comment, move the debug log into sendCommandAsync
maobaolong Sep 15, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
13 changes: 11 additions & 2 deletions hadoop-hdds/client/src/main/java/org/apache/hadoop/hdds/scm/XceiverClientGrpc.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -58,6 +58,7 @@
import io.opentracing.Scope;
import io.opentracing.Span;
import io.opentracing.util.GlobalTracer;
import org.apache.hadoop.util.Time;
import org.apache.ratis.thirdparty.io.grpc.ManagedChannel;
import org.apache.ratis.thirdparty.io.grpc.Status;
import org.apache.ratis.thirdparty.io.grpc.netty.GrpcSslContexts;
Expand Down Expand Up @@ -329,8 +330,11 @@ private XceiverClientReply sendCommandWithRetry(
}
}

int index = -1;
for (DatanodeDetails dn : datanodeList) {
index++;
try {
long startTime = Time.monotonicNow();
if (LOG.isDebugEnabled()) {
LOG.debug("Executing command {} on datanode {}", request, dn);
}
Expand All @@ -339,6 +343,11 @@ private XceiverClientReply sendCommandWithRetry(
// in case these don't exist for the specific datanode.
reply.addDatanode(dn);
responseProto = sendCommandAsync(request, dn).getResponse().get();
if (LOG.isDebugEnabled()) {

@xiaoyuyao xiaoyuyao Jul 28, 2020

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In sendCommandAsync() below we already have a LOG.debug(cmdType, Dn). Can you move this there to avoid duplicate debug log?

@maobaolong maobaolong Jul 30, 2020

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@xiaoyuyao I hope so, but I think it would be difficult, because, i want to log the retry index and cost time.
when the sendCommandAsync return back, the client still doesn't get the result from datanode. the result return until the get return.

If i have something wrong, please correct me.

@xiaoyuyao xiaoyuyao Sep 10, 2020

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I mean if we could move the LOG for latency around Line 464 where the container op latency metrics are updated. This way, we can piggyback LOG with the existing metrics update.

metrics.addContainerOpsLatency(request.getCmdType(),
System.nanoTime() - requestTime);

@maobaolong maobaolong Sep 15, 2020 •
edited
Loading

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@xiaoyuyao Thanks you for your reply and suggestion. I tried to add the LOG into the L464, like following

              public void onNext(ContainerCommandResponseProto value) {
                replyFuture.complete(value);
                metrics.decrPendingContainerOpsMetrics(request.getCmdType());
                long cost = System.nanoTime() - requestTime;
                metrics.addContainerOpsLatency(request.getCmdType(),
                    cost);
                if (LOG.isDebugEnabled()) {
                  LOG.debug("Executed command {} on datanode {}, cost = {}, "
                          + "retryCount = {}" + ", cmdType = {}", request, dn,
                      cost, index, request.getCmdType());
                }
                semaphore.release();
              }

But, there are some question

  • It cannot print the Index which stand for the retried datanode index of the datanodeList.
  • I should add the same log logic to the onError also? Otherwise, when we met error, the onNext won't be executed.

As index can be calculate from the log context, I drop it.

LOG.debug("Executed command {} on datanode {}, cost = {}, "
+ "retryCount = {}" + ", cmdType = {}", request, dn,
Time.monotonicNow() - startTime, index, request.getCmdType());
}
if (validators != null && !validators.isEmpty()) {
for (CheckedBiFunction validator : validators) {
validator.apply(request, responseProto);
Expand All @@ -354,7 +363,7 @@ private XceiverClientReply sendCommandWithRetry(
responseProto = null;
} catch (ExecutionException e) {
LOG.debug("Failed to execute command {} on datanode {}",
Comment thread
xiaoyuyao marked this conversation as resolved.
request, dn.getUuid(), e);
Comment thread
xiaoyuyao marked this conversation as resolved.
request, dn, e);
if (Status.fromThrowable(e.getCause()).getCode()
== Status.UNAUTHENTICATED.getCode()) {
throw new SCMSecurityException("Failed to authenticate with "
Expand Down Expand Up @@ -433,7 +442,7 @@ public XceiverClientReply sendCommandAsync(
UUID dnId = dn.getUuid();
if (LOG.isDebugEnabled()) {
LOG.debug("Send command {} to datanode {}",
request.getCmdType(), dn.getNetworkFullPath());
request.getCmdType(), dn);

@xiaoyuyao xiaoyuyao Aug 4, 2020

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Correct me if I'm wrong, I think we have already print the same debug message on Line 338-340 from the caller. Print just the IP address should be sufficient.

@maobaolong maobaolong Aug 10, 2020

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

OK, you are right, the redundancy log content is useless, I've change it to dn.getIpAddress().

}
final CompletableFuture<ContainerCommandResponseProto> replyFuture =
new CompletableFuture<>();
Expand Down