HADOOP-16531. Log more timing information for slow RPCs. Contributed by Chen Zhang.

This commit is contained in:
Erik Krogen 2019-09-06 10:28:21 -07:00
parent 9637097ef9
commit a23417533e

View File

@ -508,7 +508,7 @@ protected void setLogSlowRPC(boolean logSlowRPCFlag) {
* Logs a Slow RPC Request.
*
* @param methodName - RPC Request method name
* @param processingTime - Processing Time.
* @param details - Processing Detail.
*
* if this request took too much time relative to other requests
* we consider that as a slow RPC. 3 is a magic number that comes
@ -517,7 +517,8 @@ protected void setLogSlowRPC(boolean logSlowRPCFlag) {
* if and only if it falls above 99.7% of requests. We start this logic
* only once we have enough sample size.
*/
void logSlowRpcCalls(String methodName, Call call, long processingTime) {
void logSlowRpcCalls(String methodName, Call call,
ProcessingDetails details) {
final int deviation = 3;
// 1024 for minSampleSize just a guess -- not a number computed based on
@ -528,10 +529,15 @@ void logSlowRpcCalls(String methodName, Call call, long processingTime) {
final double threeSigma = rpcMetrics.getProcessingMean() +
(rpcMetrics.getProcessingStdDev() * deviation);
long processingTime =
details.get(Timing.PROCESSING, RpcMetrics.TIMEUNIT);
if ((rpcMetrics.getProcessingSampleCount() > minSampleSize) &&
(processingTime > threeSigma)) {
LOG.warn("Slow RPC : {} took {} {} to process from client {}",
methodName, processingTime, RpcMetrics.TIMEUNIT, call);
LOG.warn(
"Slow RPC : {} took {} {} to process from client {},"
+ " the processing detail is {}",
methodName, processingTime, RpcMetrics.TIMEUNIT, call,
details.toString());
rpcMetrics.incrSlowRpc();
}
}
@ -570,7 +576,7 @@ void updateMetrics(Call call, long startTime, boolean connDropped) {
rpcDetailedMetrics.addProcessingTime(name, processingTime);
callQueue.addResponseTime(name, call, details);
if (isLogSlowRPC()) {
logSlowRpcCalls(name, call, processingTime);
logSlowRpcCalls(name, call, details);
}
}