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

(cherry picked from commit a23417533e)

hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/ipc/Server.java

@@ -507,7 +507,7 @@ public abstract class Server {
    * 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
@@ -516,7 +516,8 @@ public abstract class Server {
    * 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
@@ -527,10 +528,15 @@ public abstract class Server {
     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();
     }
   }
@@ -569,7 +575,7 @@ public abstract class Server {
     rpcDetailedMetrics.addProcessingTime(name, processingTime);
     callQueue.addResponseTime(name, call, details);
     if (isLogSlowRPC()) {
-      logSlowRpcCalls(name, call, processingTime);
+      logSlowRpcCalls(name, call, details);
     }
   }