From a4fe4c61551c9f15706e22972ccea1ad0203e6f1 Mon Sep 17 00:00:00 2001 From: siyuan0322 Date: Tue, 24 Sep 2024 21:27:00 +0800 Subject: [PATCH] refine logs --- .../common/client/RpcExecutionClient.java | 5 ++++ .../cypher/result/CypherRecordProcessor.java | 3 +-- .../gremlin/plugin/QueryStatusCallback.java | 24 +++++++++---------- .../processor/IrStandardOpProcessor.java | 7 +++--- .../processor/AbstractResultProcessor.java | 3 ++- .../resultx/GremlinResultProcessor.java | 3 +-- 6 files changed, 24 insertions(+), 21 deletions(-) diff --git a/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/common/client/RpcExecutionClient.java b/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/common/client/RpcExecutionClient.java index a753c39a29cd..2920d2d5accd 100644 --- a/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/common/client/RpcExecutionClient.java +++ b/interactive_engine/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 { + Logger logger = LoggerFactory.getLogger(RpcExecutionClient.class); private final Configs graphConfig; private final AtomicReference 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/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/cypher/result/CypherRecordProcessor.java b/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/cypher/result/CypherRecordProcessor.java index 2f428cba2874..b39e2d8eadc6 100644 --- a/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/cypher/result/CypherRecordProcessor.java +++ b/interactive_engine/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/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/gremlin/plugin/QueryStatusCallback.java b/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/gremlin/plugin/QueryStatusCallback.java index cd7059699e0f..2f45930159a1 100644 --- a/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/gremlin/plugin/QueryStatusCallback.java +++ b/interactive_engine/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 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 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 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/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/gremlin/plugin/processor/IrStandardOpProcessor.java b/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/gremlin/plugin/processor/IrStandardOpProcessor.java index a297e0451864..8ac1f418e99a 100644 --- a/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/gremlin/plugin/processor/IrStandardOpProcessor.java +++ b/interactive_engine/compiler/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/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/gremlin/result/processor/AbstractResultProcessor.java b/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/gremlin/result/processor/AbstractResultProcessor.java index 3447f782b308..419286a5532d 100644 --- a/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/gremlin/result/processor/AbstractResultProcessor.java +++ b/interactive_engine/compiler/src/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/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/gremlin/resultx/GremlinResultProcessor.java b/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/gremlin/resultx/GremlinResultProcessor.java index 1bd77c8bb895..b1fe008adced 100644 --- a/interactive_engine/compiler/src/main/java/com/alibaba/graphscope/gremlin/resultx/GremlinResultProcessor.java +++ b/interactive_engine/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 results = Lists.newArrayList(); if (resultSchema.isGroupBy) { results.add(reducer);