From a4584bc2713c0a43c8fe798b10a0badeb43208e0 Mon Sep 17 00:00:00 2001 From: endigma Date: Tue, 22 Jul 2025 12:07:27 +0100 Subject: [PATCH 1/2] Add log when planning time exceeds threshhold --- router/core/graphql_prehandler.go | 22 +++++++++++++++++++--- 1 file changed, 19 insertions(+), 3 deletions(-) diff --git a/router/core/graphql_prehandler.go b/router/core/graphql_prehandler.go index cb856573bb..e64d9748a6 100644 --- a/router/core/graphql_prehandler.go +++ b/router/core/graphql_prehandler.go @@ -966,6 +966,7 @@ func (h *PreHandler) handleOperation(req *http.Request, variablesParser *astjson if !requestContext.operation.traceOptions.ExcludePlannerStats { httpOperation.traceTimings.StartPlanning() } + startPlanning := time.Now() _, enginePlanSpan := h.tracer.Start(req.Context(), "Operation - Plan", @@ -984,22 +985,26 @@ func (h *PreHandler) handleOperation(req *http.Request, variablesParser *astjson err = h.planner.plan(requestContext.operation, planOptions) if err != nil { httpOperation.requestLogger.Debug("failed to plan operation", zap.Error(err)) - rtrace.AttachErrToSpan(enginePlanSpan, err) if !requestContext.operation.traceOptions.ExcludePlannerStats { httpOperation.traceTimings.EndPlanning() } + requestContext.operation.planningTime = time.Since(startPlanning) + + rtrace.AttachErrToSpan(enginePlanSpan, err) enginePlanSpan.End() return err } - enginePlanSpan.SetAttributes(otel.WgEnginePlanCacheHit.Bool(requestContext.operation.planCacheHit)) + if !requestContext.operation.traceOptions.ExcludePlannerStats { + httpOperation.traceTimings.EndPlanning() + } requestContext.operation.planningTime = time.Since(startPlanning) - httpOperation.traceTimings.EndPlanning() + enginePlanSpan.SetAttributes(otel.WgEnginePlanCacheHit.Bool(requestContext.operation.planCacheHit)) enginePlanSpan.End() planningAttrs := *requestContext.telemetry.AcquireAttributes() @@ -1015,6 +1020,17 @@ func (h *PreHandler) handleOperation(req *http.Request, variablesParser *astjson requestContext.telemetry.ReleaseAttributes(&planningAttrs) + if requestContext.operation.planningTime > 4*time.Second { + h.log.Warn("Planning time exceeded threshold", + zap.Duration("planning_time", requestContext.operation.planningTime), + zap.String("operation_id", requestContext.operation.name), + zap.String("operation_type", requestContext.operation.opType), + zap.String("operation_client", requestContext.operation.clientInfo.Name), + zap.String("operation_client_version", requestContext.operation.clientInfo.Version), + zap.String("operation_content", requestContext.operation.content), + ) + } + // we could log the query plan only if query plans are calculated if (h.queryPlansEnabled && requestContext.operation.executionOptions.IncludeQueryPlanInResponse) || h.alwaysIncludeQueryPlan { From 9f6c4a099edeef2e9476ac54cfefb332665297e0 Mon Sep 17 00:00:00 2001 From: endigma Date: Fri, 15 Aug 2025 10:01:22 +0100 Subject: [PATCH 2/2] Remove planning time log warning --- router/core/graphql_prehandler.go | 11 ----------- 1 file changed, 11 deletions(-) diff --git a/router/core/graphql_prehandler.go b/router/core/graphql_prehandler.go index e64d9748a6..3c9ca3f976 100644 --- a/router/core/graphql_prehandler.go +++ b/router/core/graphql_prehandler.go @@ -1020,17 +1020,6 @@ func (h *PreHandler) handleOperation(req *http.Request, variablesParser *astjson requestContext.telemetry.ReleaseAttributes(&planningAttrs) - if requestContext.operation.planningTime > 4*time.Second { - h.log.Warn("Planning time exceeded threshold", - zap.Duration("planning_time", requestContext.operation.planningTime), - zap.String("operation_id", requestContext.operation.name), - zap.String("operation_type", requestContext.operation.opType), - zap.String("operation_client", requestContext.operation.clientInfo.Name), - zap.String("operation_client_version", requestContext.operation.clientInfo.Version), - zap.String("operation_content", requestContext.operation.content), - ) - } - // we could log the query plan only if query plans are calculated if (h.queryPlansEnabled && requestContext.operation.executionOptions.IncludeQueryPlanInResponse) || h.alwaysIncludeQueryPlan {