From 4e0109dab015cbe54b9b06db1354c47dd712605e Mon Sep 17 00:00:00 2001 From: fantasy <875282031@qq.com> Date: Tue, 16 Aug 2022 22:46:42 +0800 Subject: [PATCH 1/2] In trace log mode, the client does not print callId/startTime and the server does not print receiveTime, so fix it --- .../java/org/apache/hadoop/hbase/ipc/AbstractRpcClient.java | 3 ++- .../main/java/org/apache/hadoop/hbase/ipc/RpcServer.java | 6 +++--- 2 files changed, 5 insertions(+), 4 deletions(-) diff --git a/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/AbstractRpcClient.java b/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/AbstractRpcClient.java index e5863948a58c..d8f4b96bf0aa 100644 --- a/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/AbstractRpcClient.java +++ b/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/AbstractRpcClient.java @@ -380,7 +380,8 @@ private void onCallFinished(Call call, HBaseRpcController hrc, Address addr, } if (LOG.isTraceEnabled()) { LOG.trace( - "Call: " + call.md.getName() + ", callTime: " + call.callStats.getCallTimeMs() + "ms"); + "CallId: {}, call: {}, startTime: {}ms, callTime: {}ms", call.id, call.getStartTime(), + call.md.getName(), call.callStats.getCallTimeMs()); } if (call.error != null) { if (call.error instanceof RemoteException) { diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java index 966b13aa869c..d39ef2a782b8 100644 --- a/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java +++ b/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java @@ -390,9 +390,9 @@ public Pair call(RpcCall call, MonitoredRPCHandler status) int qTime = (int) (startTime - receiveTime); int totalTime = (int) (endTime - receiveTime); if (LOG.isTraceEnabled()) { - LOG.trace(CurCall.get().toString() + ", response " + TextFormat.shortDebugString(result) - + " queueTime: " + qTime + " processingTime: " + processingTime + " totalTime: " - + totalTime); + LOG.trace("{}, response: {}, receiveTime: {}, queueTime: {}, processingTime: {}, totalTime: {}", + CurCall.get().toString(), TextFormat.shortDebugString(result), CurCall.get().getReceiveTime(), + qTime, processingTime, totalTime); } // Use the raw request call size for now. long requestSize = call.getSize(); From c906356202d993c107eea297590e93a5ca5aed65 Mon Sep 17 00:00:00 2001 From: "jay.zhu" Date: Wed, 17 Aug 2022 16:06:28 +0800 Subject: [PATCH 2/2] HBASE-27268 In trace log mode, the client does not print callId/startTime and the server does not print receiveTime --- .../org/apache/hadoop/hbase/ipc/AbstractRpcClient.java | 5 ++--- .../main/java/org/apache/hadoop/hbase/ipc/RpcServer.java | 7 ++++--- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/AbstractRpcClient.java b/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/AbstractRpcClient.java index d8f4b96bf0aa..0afd07d79513 100644 --- a/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/AbstractRpcClient.java +++ b/hbase-client/src/main/java/org/apache/hadoop/hbase/ipc/AbstractRpcClient.java @@ -379,9 +379,8 @@ private void onCallFinished(Call call, HBaseRpcController hrc, Address addr, metrics.updateRpc(call.md, call.param, call.callStats); } if (LOG.isTraceEnabled()) { - LOG.trace( - "CallId: {}, call: {}, startTime: {}ms, callTime: {}ms", call.id, call.getStartTime(), - call.md.getName(), call.callStats.getCallTimeMs()); + LOG.trace("CallId: {}, call: {}, startTime: {}ms, callTime: {}ms", call.id, call.md.getName(), + call.getStartTime(), call.callStats.getCallTimeMs()); } if (call.error != null) { if (call.error instanceof RemoteException) { diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java index d39ef2a782b8..15caac476f35 100644 --- a/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java +++ b/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/RpcServer.java @@ -390,9 +390,10 @@ public Pair call(RpcCall call, MonitoredRPCHandler status) int qTime = (int) (startTime - receiveTime); int totalTime = (int) (endTime - receiveTime); if (LOG.isTraceEnabled()) { - LOG.trace("{}, response: {}, receiveTime: {}, queueTime: {}, processingTime: {}, totalTime: {}", - CurCall.get().toString(), TextFormat.shortDebugString(result), CurCall.get().getReceiveTime(), - qTime, processingTime, totalTime); + LOG.trace( + "{}, response: {}, receiveTime: {}, queueTime: {}, processingTime: {}, totalTime: {}", + CurCall.get().toString(), TextFormat.shortDebugString(result), + CurCall.get().getReceiveTime(), qTime, processingTime, totalTime); } // Use the raw request call size for now. long requestSize = call.getSize();