[incubator-uniffle] branch master updated: Log enhancement: Merge multiple logs into oneline and add more description (#62)

[roryqi]

This is an automated email from the ASF dual-hosted git repository.

roryqi pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/incubator-uniffle.git


The following commit(s) were added to refs/heads/master by this push:
     new 2fff3f7  Log enhancement: Merge multiple logs into oneline and add 
more description  (#62)
2fff3f7 is described below

commit 2fff3f7d0f34bf58a63cd2ffe8ea6b1497274abf
Author: Junfan Zhang <junfan.zh...@outlook.com>
AuthorDate: Thu Jul 21 14:47:16 2022 +0800

    Log enhancement: Merge multiple logs into oneline and add more description  
(#62)
    
    ### What changes were proposed in this pull request?
    Log enhancement: Merge multiple logs into oneline and add more description
    
    ### Why are the changes needed?
    Adding more description to analyze the request time cost.
    
    ### Does this PR introduce _any_ user-facing change?
    No
    
    ### How was this patch tested?
    No need
---
 .../org/apache/uniffle/client/impl/ShuffleWriteClientImpl.java | 10 +++++-----
 .../uniffle/client/impl/grpc/ShuffleServerGrpcClient.java      |  8 ++++++--
 2 files changed, 11 insertions(+), 7 deletions(-)

diff --git 
a/client/src/main/java/org/apache/uniffle/client/impl/ShuffleWriteClientImpl.java
 
b/client/src/main/java/org/apache/uniffle/client/impl/ShuffleWriteClientImpl.java
index b078d42..4ba62d7 100644
--- 
a/client/src/main/java/org/apache/uniffle/client/impl/ShuffleWriteClientImpl.java
+++ 
b/client/src/main/java/org/apache/uniffle/client/impl/ShuffleWriteClientImpl.java
@@ -134,17 +134,17 @@ public class ShuffleWriteClientImpl implements 
ShuffleWriteClient {
               appId, retryMax, retryIntervalMax, shuffleIdToBlocks);
           long s = System.currentTimeMillis();
           RssSendShuffleDataResponse response = 
getShuffleServerClient(ssi).sendShuffleData(request);
-          LOG.info("ShuffleWriteClientImpl sendShuffleData cost:" + 
(System.currentTimeMillis() - s) + "(ms)");
+
+          String logMsg = String.format("ShuffleWriteClientImpl 
sendShuffleData with %s blocks to %s cost: %s(ms)",
+              serverToBlockIds.get(ssi).size(), ssi.getId(), 
System.currentTimeMillis() - s);
 
           if (response.getStatusCode() == ResponseStatusCode.SUCCESS) {
             // mark a replica of block that has been sent
             serverToBlockIds.get(ssi).forEach(block -> 
blockIdsTracker.get(block).incrementAndGet());
-            LOG.info("Send: " + serverToBlockIds.get(ssi).size()
-                + " blocks to [" + ssi.getId() + "] successfully");
+            LOG.info("{} successfully.", logMsg);
           } else {
             isAllServersSuccess.set(false);
-            LOG.warn("Send: " + serverToBlockIds.get(ssi).size() + " blocks to 
[" + ssi.getId()
-                + "] failed with statusCode[" + response.getStatusCode() + "], 
");
+            LOG.warn("{}, it failed wth statusCode[{}]", logMsg, 
response.getStatusCode());
           }
         } catch (Exception e) {
           isAllServersSuccess.set(false);
diff --git 
a/internal-client/src/main/java/org/apache/uniffle/client/impl/grpc/ShuffleServerGrpcClient.java
 
b/internal-client/src/main/java/org/apache/uniffle/client/impl/grpc/ShuffleServerGrpcClient.java
index fed8c92..ce3d7cd 100644
--- 
a/internal-client/src/main/java/org/apache/uniffle/client/impl/grpc/ShuffleServerGrpcClient.java
+++ 
b/internal-client/src/main/java/org/apache/uniffle/client/impl/grpc/ShuffleServerGrpcClient.java
@@ -163,6 +163,7 @@ public class ShuffleServerGrpcClient extends GrpcClient 
implements ShuffleServer
 
   public long requirePreAllocation(int requireSize, int retryMax, long 
retryIntervalMax) {
     RequireBufferRequest rpcRequest = 
RequireBufferRequest.newBuilder().setRequireSize(requireSize).build();
+    long start = System.currentTimeMillis();
     RequireBufferResponse rpcResponse = blockingStub.withDeadlineAfter(
         RPC_TIMEOUT_DEFAULT_MS, 
TimeUnit.MILLISECONDS).requireBuffer(rpcRequest);
     int retry = 0;
@@ -174,7 +175,8 @@ public class ShuffleServerGrpcClient extends GrpcClient 
implements ShuffleServer
           + retry + "] again");
       if (retry >= retryMax) {
         LOG.warn("ShuffleServer " + host + ":" + port + " is full and can't 
send shuffle"
-            + " data successfully after retry " + retryMax + " times");
+            + " data successfully after retry " + retryMax + " times, cost: 
{}(ms)",
+            System.currentTimeMillis() - start);
         return result;
       }
       try {
@@ -182,13 +184,15 @@ public class ShuffleServerGrpcClient extends GrpcClient 
implements ShuffleServer
             Math.min(retryIntervalMax, backOffBase * (1 << Math.min(retry, 
16)) + random.nextInt(backOffBase));
         Thread.sleep(backoffTime);
       } catch (Exception e) {
-        LOG.warn("Exception happened when require pre allocation", e);
+        LOG.warn("Exception happened when require pre allocation from " + host 
+ ":" + port, e);
       }
       rpcResponse = blockingStub.withDeadlineAfter(
           RPC_TIMEOUT_DEFAULT_MS, 
TimeUnit.MILLISECONDS).requireBuffer(rpcRequest);
       retry++;
     }
     if (rpcResponse.getStatus() == StatusCode.SUCCESS) {
+      LOG.info("Require preAllocated size of {} from {}:{}, cost: {}(ms)",
+          requireSize, host, port, System.currentTimeMillis() - start);
       result = rpcResponse.getRequireBufferId();
     }
     return result;