yandrey321 commented on code in PR #11294:
URL: https://github.com/apache/ozone/pull/11294#discussion_r4076029702
##########
hadoop-hdds/client/src/main/java/org/apache/hadoop/hdds/scm/XceiverClientShortCircuit.java:
##########
@@ -511,27 +485,24 @@ public void run() {
}
long currentTime = System.nanoTime();
long endToEndCost = currentTime - entry.getCreateTimeNs();
- long sentCost = entry.getSentTimeNs() - entry.getCreateTimeNs();
- long receiveCost = processStartTime - receiveStartTime;
- long processCost = currentTime - processStartTime;
if (LOG.isDebugEnabled()) {
- LOG.debug("Executed command {} {}:{} on datanode {}, end-to-end {}
ns, sent {} ns, receive {} ns, " +
- "process {} ns", type,
entry.getRequest().getClientId().toStringUtf8(),
- entry.getRequest().getCallId(), dn, endToEndCost, sentCost,
receiveCost, processCost);
+ LOG.debug("Executed command {} {}:{} on datanode {}, end-to-end
{}ms, receive {}ms, process {}ms",
+ type, entry.getRequest().getClientId().toStringUtf8(),
entry.getRequest().getCallId(), dn,
+ nsToMs(endToEndCost),
+ nsToMs(processStartTime - receiveStartTime),
+ nsToMs(currentTime - processStartTime));
}
- responseReceived++;
+ responseReceived.incrementAndGet();
metrics.decrPendingContainerOpsMetrics(type);
metrics.addContainerOpsLatency(type, endToEndCost);
} catch (SocketTimeoutException | EOFException |
ClosedChannelException e) {
isDomainSocketOpen.set(false);
- LOG.info("{} receiveResponseTask is closed after send {} requests
and received {} responses, due to {}",
- domainSocket.toString(), requestSent, responseReceived,
e.getClass().getName(), e);
+ LOG.debug("ReceiveResponseTask closed: {}", this, e);
Review Comment:
ReceiveResponseTask is a non-static inner class with no toString(), so
`this` here (and at
line 505) formats as XceiverClientShortCircuit$ReceiveResponseTask@1f2a3b4c.
The intent looks
like XceiverClientShortCircuit.this, which is exactly what the new `name`
field was added for.
Three losses stack up on the line that tells you why the read loop died:
- the object is an identity hash instead of the socket + datanode
- `requestSent` / `responseReceived` were dropped (the old message carried
both)
- it was demoted from LOG.info to LOG.debug
So at default log levels a short-circuit client whose receive loop shuts
down on
EOF/SocketTimeout/ClosedChannel now produces no record at all. Given the
stated goal is better
diagnostics, I'd keep this at INFO with XceiverClientShortCircuit.this and
the two counters.
Line 505 has the same `this` problem (that one is at least still ERROR).
##########
hadoop-hdds/client/src/main/java/org/apache/hadoop/hdds/scm/XceiverClientShortCircuit.java:
##########
@@ -254,63 +264,33 @@ private XceiverClientReply sendCommandWithTraceID(
try {
if (LOG.isDebugEnabled()) {
- LOG.debug("Executing command {} on datanode {}", request, dn);
- }
- reply.addDatanode(dn);
- responseProto =
sendCommandInternal(finalPayload).getResponse().get();
- if (validators != null && !validators.isEmpty()) {
- for (Validator validator : validators) {
- validator.accept(request, responseProto);
- }
+ LOG.debug("Executing {} on {}", processForDebug(request), dn);
}
+ response = sendCommandInternal(finalPayload);
Review Comment:
Before this change the blocking get() was inside the span:
responseProto = sendCommandInternal(finalPayload).getResponse().get();
so the span measured the full round trip. Now sendCommandInternal returns a
pending future and
the get() has moved out to both sendCommand overloads, which means
executeInNewSpan closes as
soon as the request has been written to the socket. Every
XceiverClientShortCircuit.GetBlock / .Echo span collapses to
request-construction + socket-write
time, and the actual latency — the thing the span exists to measure — is no
longer inside it.
Since sendCommandAsync is UnsupportedOperationException and
sendCommandWithTraceID is only
reached from the two sendCommand overloads that immediately get(), nothing
needs the pending
future. Could the get() stay inside the span (or the span be closed via
future.whenComplete(...)) so tracing keeps measuring the operation?
Related, line 271: `LOG.debug("request {} {} {} finished", ...)` now fires
when the request is
*sent*, not finished. Worth rewording or moving.
##########
hadoop-hdds/client/src/main/java/org/apache/hadoop/hdds/scm/XceiverClientShortCircuit.java:
##########
@@ -653,4 +624,35 @@ public boolean equals(Object obj) {
&& this.blockLocalId == that.blockLocalId;
}
}
+
+ static final class TimeoutScheduler {
+ private Timer timer;
+
+ synchronized void init(String prefix) {
+ Preconditions.assertNull(timer, "timer");
+ timer = new Timer(prefix + "-Timer");
+ }
+
+ synchronized void schedule(TimerTask task, int timeoutMs) {
+ if (timer == null) {
Review Comment:
purge() and close() no-oping on a null timer is fine, but schedule() is
different in kind: if
the timer is gone the request is registered in sentRequests with no timeout
at all, and
sendCommand's `.getResponse().get()` is unbounded, so the read timeout is
the only thing
bounding that call.
checkOpen() and close() are both synchronized on `this`, but sendRequest
runs after checkOpen
releases the monitor, so a close() in between reaches this no-op. Today the
subsequent write to
the closed socket throws and completes the future exceptionally, so it
doesn't hang in
practice — but that makes liveness depend on the write failing rather than
on anything
explicit. Would it be better to fail the entry (or throw) when timer ==
null, so "no timeout
was scheduled" can never be silent?
##########
hadoop-hdds/client/src/main/java/org/apache/hadoop/hdds/scm/XceiverClientShortCircuit.java:
##########
@@ -653,4 +624,35 @@ public boolean equals(Object obj) {
&& this.blockLocalId == that.blockLocalId;
}
}
+
+ static final class TimeoutScheduler {
+ private Timer timer;
+
+ synchronized void init(String prefix) {
+ Preconditions.assertNull(timer, "timer");
Review Comment:
connect() guards with
if (domainSocket != null && domainSocket.isOpen() &&
isDomainSocketOpen.get()) return;
and the comment above it ("Even the in & out stream has returned
EOFException,
domainSocket.isOpen() is still true") says the isDomainSocketOpen term is
there precisely so a
post-EOF connect() falls through and re-creates the socket. On that path
init() now hits Preconditions.assertNull(timer, "timer") and throws
IllegalStateException, where master simply replaced the field.
##########
hadoop-hdds/client/src/main/java/org/apache/hadoop/hdds/scm/XceiverClientShortCircuit.java:
##########
@@ -542,6 +513,10 @@ public void run() {
}
}
+ static long nsToMs(long ns) {
Review Comment:
would we expect most of ops to consume 1+ ms, or should we expect sub-ms
latency for short circuit reads?
##########
hadoop-hdds/client/src/main/java/org/apache/hadoop/hdds/scm/XceiverClientShortCircuit.java:
##########
Review Comment:
this `continue` skips metrics.decrPendingContainerOpsMetrics(type) and
addContainerOpsLatency() below, whilevthe entry has already been removed from
sentRequests and its timer cancelled. Every FD-exchange failure therefore leaks
the pending-container-ops gauge upward permanently.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
