refine logs

alibaba · Sep 24, 2024 · a4fe4c6 · a4fe4c6
1 parent 504558c
commit a4fe4c6
Show file tree

Hide file tree

Showing 6 changed files with 24 additions and 21 deletions.
diff --git a/...ngine/compiler/src/main/java/com/alibaba/graphscope/common/client/RpcExecutionClient.java b/...ngine/compiler/src/main/java/com/alibaba/graphscope/common/client/RpcExecutionClient.java
@@ -31,12 +31,16 @@
 
 import io.grpc.Status;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
 import java.util.concurrent.atomic.AtomicReference;
 
 /**
  * rpc client to send request to pegasus engine service
  */
 public class RpcExecutionClient extends ExecutionClient<RpcChannel> {
+    Logger logger = LoggerFactory.getLogger(RpcExecutionClient.class);
     private final Configs graphConfig;
     private final AtomicReference<RpcClient> rpcClientRef;
 
@@ -93,6 +97,7 @@ public void process(PegasusClient.JobResponse jobResponse) {
                     @Override
                     public void finish() {
                         listener.onCompleted();
+                        logger.info("[compile]: received results from engine");
                     }
 
                     @Override

diff --git a/...ne/compiler/src/main/java/com/alibaba/graphscope/cypher/result/CypherRecordProcessor.java b/...ne/compiler/src/main/java/com/alibaba/graphscope/cypher/result/CypherRecordProcessor.java
@@ -25,7 +25,6 @@
 import com.alibaba.graphscope.gremlin.plugin.QueryStatusCallback;
 import com.alibaba.graphscope.proto.frontend.Code;
 import com.alibaba.pegasus.common.StreamIterator;
-import com.google.common.collect.ImmutableList;
 
 import org.neo4j.fabric.stream.summary.EmptySummary;
 import org.neo4j.fabric.stream.summary.Summary;
@@ -137,7 +136,7 @@ public void onNext(IrResult.Record record) {
     public void onCompleted() {
         try {
             this.recordIterator.finish();
-            this.statusCallback.onSuccessEnd(ImmutableList.of());
+            this.statusCallback.onSuccessEnd();
         } catch (InterruptedException e) {
             onError(e);
         }

diff --git a/...ine/compiler/src/main/java/com/alibaba/graphscope/gremlin/plugin/QueryStatusCallback.java b/...ine/compiler/src/main/java/com/alibaba/graphscope/gremlin/plugin/QueryStatusCallback.java
@@ -17,7 +17,6 @@
 package com.alibaba.graphscope.gremlin.plugin;
 
 import com.alibaba.graphscope.groot.common.constant.LogConstant;
-import com.alibaba.graphscope.groot.common.util.JSON;
 import com.google.gson.JsonObject;
 
 import io.opentelemetry.api.common.Attributes;
@@ -26,8 +25,6 @@
 
 import org.checkerframework.checker.nullness.qual.Nullable;
 
-import java.util.List;
-
 public class QueryStatusCallback {
     private final MetricsCollector metricsCollector;
     private final QueryLogger queryLogger;
@@ -65,7 +62,7 @@ public void onErrorEnd(Throwable t, String msg) {
             errorMsg = t.getMessage();
         }
         JsonObject logJson = buildSimpleLog(false, metricsCollector.getElapsedMillis());
-        fillLogDetail(logJson, errorMsg, metricsCollector.getStartMillis(), null);
+        fillLogDetail(logJson, errorMsg, metricsCollector.getStartMillis());
         queryLogger.print(logJson.toString(), false, t);
 
         Attributes attrs =
@@ -81,10 +78,11 @@ public void onErrorEnd(Throwable t, String msg) {
         queryLogger.metricsInfo(false, metricsCollector.getElapsedMillis());
     }
 
-    public void onSuccessEnd(List<Object> results) {
+    public void onSuccessEnd() {
         this.metricsCollector.stop();
+        queryLogger.info("total execution time is {} ms", metricsCollector.getElapsedMillis());
         JsonObject logJson = buildSimpleLog(true, metricsCollector.getElapsedMillis());
-        fillLogDetail(logJson, null, results);
+        fillLogDetail(logJson, null);
         queryLogger.print(logJson.toString(), true, null);
 
         Attributes attrs =
@@ -113,24 +111,24 @@ private JsonObject buildSimpleLog(boolean isSucceed, long elapsedMillis) {
         return simpleJson;
     }
 
-    private void fillLogDetail(JsonObject logJson, String errorMsg, List<Object> results) {
+    private void fillLogDetail(JsonObject logJson, String errorMsg) {
         try {
             if (this.metricsCollector.getElapsedMillis() > this.printThreshold) {
                 // todo(siyuan): the invocation of the function can cause Exception when serializing
                 // a gremlin vertex to json format
-                fillLogDetail(logJson, errorMsg, metricsCollector.getStartMillis(), results);
+                fillLogDetail(logJson, errorMsg, metricsCollector.getStartMillis());
             }
         } catch (Throwable t) {
             queryLogger.warn("fill log detail error", t);
         }
     }
 
-    private void fillLogDetail(
-            JsonObject logJson, String errorMessage, long startMillis, List<Object> results) {
+    private void fillLogDetail(JsonObject logJson, String errorMessage, long startMillis) {
         logJson.addProperty(LogConstant.QUERY, queryLogger.getQuery());
-        if (results != null) {
-            logJson.addProperty(LogConstant.RESULT, JSON.toJson(results));
-        }
+        // do not serialize result.
+        //        if (results != null) {
+        //            logJson.addProperty(LogConstant.RESULT, JSON.toJson(results));
+        //        }
         if (errorMessage != null) {
             logJson.addProperty(LogConstant.ERROR_MESSAGE, errorMessage);
         }

diff --git a/.../src/main/java/com/alibaba/graphscope/gremlin/plugin/processor/IrStandardOpProcessor.java b/.../src/main/java/com/alibaba/graphscope/gremlin/plugin/processor/IrStandardOpProcessor.java
@@ -200,6 +200,7 @@ protected void evalOpInternal(
                         new MetricsCollector.Gremlin(evalOpTimer),
                         queryHistogram,
                         configs);
+        statusCallback.getQueryLogger().info("[compile]: query received");
         QueryTimeoutConfig timeoutConfig = new QueryTimeoutConfig(ctx.getRequestTimeout());
         GremlinExecutor.LifeCycle lifeCycle;
         switch (language) {
@@ -360,6 +361,7 @@ protected GremlinExecutor.LifeCycle createLifeCycle(
                             if (o != null && o instanceof Traversal) {
                                 applyStrategies((Traversal) o);
                             }
+                            statusCallback.getQueryLogger().info("[compile]: traversal compiled");
                             return o;
                         })
                 .withResult(
@@ -404,9 +406,8 @@ protected void processTraversal(
                             return opCollection;
                         },
                         Code.LOGICAL_PLAN_BUILD_FAILED);
-
+        queryLogger.info("[compile]: logical IR compiled");
         StringBuilder irPlanStr = new StringBuilder();
-
         PegasusClient.JobRequest physicalRequest =
                 ClassUtils.callException(
                         () -> {
@@ -450,7 +451,7 @@ protected void processTraversal(
                             return request;
                         },
                         Code.PHYSICAL_PLAN_BUILD_FAILED);
-
+        queryLogger.info("[compile]: physical IR compiled");
         Span outgoing;
         // if exist up trace, useUpTraceId as current traceId
         if (TraceId.isValid(queryLogger.getUpstreamId())) {

diff --git a/...rc/main/java/com/alibaba/graphscope/gremlin/result/processor/AbstractResultProcessor.java b/...rc/main/java/com/alibaba/graphscope/gremlin/result/processor/AbstractResultProcessor.java
@@ -109,6 +109,7 @@ public void request() {
                 responseProcessor.process(responseStreamIterator.next());
             }
             responseProcessor.finish();
+            statusCallback.getQueryLogger().info("[compile]: process results success");
         } catch (Throwable t) {
             // if the exception is caused by InterruptedException, it means a timeout exception has
             // been thrown by gremlin executor
@@ -164,7 +165,7 @@ public void process(PegasusClient.JobResponse response) {
         }
 
         public void finish() {
-            statusCallback.onSuccessEnd(resultCollectors);
+            statusCallback.onSuccessEnd();
             aggregateResults();
             writeResult.writeAndFlush(
                     ResponseMessage.build(writeResult.getRequestMessage())

diff --git a/...compiler/src/main/java/com/alibaba/graphscope/gremlin/resultx/GremlinResultProcessor.java b/...compiler/src/main/java/com/alibaba/graphscope/gremlin/resultx/GremlinResultProcessor.java
@@ -27,7 +27,6 @@
 import com.alibaba.graphscope.gremlin.plugin.QueryStatusCallback;
 import com.alibaba.graphscope.proto.frontend.Code;
 import com.alibaba.pegasus.common.StreamIterator;
-import com.google.common.collect.ImmutableList;
 import com.google.common.collect.Lists;
 import com.google.common.collect.Maps;
 
@@ -149,7 +148,7 @@ protected void processRecord(IrResult.Record record) {
     }
 
     protected void finishRecord() {
-        statusCallback.onSuccessEnd(ImmutableList.of());
+        statusCallback.onSuccessEnd();
         List<Object> results = Lists.newArrayList();
         if (resultSchema.isGroupBy) {
             results.add(reducer);