From 0651b82827c8aba586f361581275280f809f9447 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Mon, 19 May 2025 21:44:38 +1000 Subject: [PATCH 01/25] adding Profiler --- src/main/java/graphql/EngineRunningState.java | 2 + src/main/java/graphql/ExecutionInput.java | 15 +++++- src/main/java/graphql/GraphQL.java | 13 +++-- src/main/java/graphql/Profiler.java | 31 +++++++++++ src/main/java/graphql/ProfilerImpl.java | 51 +++++++++++++++++++ src/main/java/graphql/ProfilerResult.java | 37 ++++++++++++++ .../java/graphql/execution/Execution.java | 6 +-- .../graphql/execution/ExecutionContext.java | 13 +++-- .../execution/ExecutionContextBuilder.java | 8 +++ .../graphql/execution/ExecutionStrategy.java | 4 +- src/test/groovy/graphql/ProfilerTest.groovy | 38 ++++++++++++++ .../AsyncExecutionStrategyTest.groovy | 6 +++ .../AsyncSerialExecutionStrategyTest.groovy | 3 ++ .../execution/ExecutionStrategyTest.groovy | 2 + .../graphql/execution/ExecutionTest.groovy | 9 ++-- .../FieldValidationTest.groovy | 3 +- 16 files changed, 221 insertions(+), 20 deletions(-) create mode 100644 src/main/java/graphql/Profiler.java create mode 100644 src/main/java/graphql/ProfilerImpl.java create mode 100644 src/main/java/graphql/ProfilerResult.java create mode 100644 src/test/groovy/graphql/ProfilerTest.groovy diff --git a/src/main/java/graphql/EngineRunningState.java b/src/main/java/graphql/EngineRunningState.java index 43b584805f..1bbbbe0754 100644 --- a/src/main/java/graphql/EngineRunningState.java +++ b/src/main/java/graphql/EngineRunningState.java @@ -2,6 +2,7 @@ import graphql.execution.EngineRunningObserver; import graphql.execution.ExecutionId; +import org.jspecify.annotations.NullMarked; import org.jspecify.annotations.Nullable; import java.util.concurrent.CompletableFuture; @@ -19,6 +20,7 @@ import static graphql.execution.EngineRunningObserver.RunningState.RUNNING_START; @Internal +@NullMarked public class EngineRunningState { @Nullable diff --git a/src/main/java/graphql/ExecutionInput.java b/src/main/java/graphql/ExecutionInput.java index 59efc4f48d..9a8a51cbba 100644 --- a/src/main/java/graphql/ExecutionInput.java +++ b/src/main/java/graphql/ExecutionInput.java @@ -31,6 +31,7 @@ public class ExecutionInput { private final Locale locale; // this is currently not used but we want it back soon after the v23 release private final AtomicBoolean cancelled; + private final boolean profileExecution; @Internal @@ -47,6 +48,7 @@ private ExecutionInput(Builder builder) { this.localContext = builder.localContext; this.extensions = builder.extensions; this.cancelled = builder.cancelled; + this.profileExecution = builder.profileExecution; } /** @@ -142,6 +144,11 @@ public Map getExtensions() { return extensions; } + + public boolean isProfileExecution() { + return profileExecution; + } + /** * This helps you transform the current ExecutionInput object into another one by starting a builder with all * the current values and allows you to transform it how you want. @@ -221,6 +228,7 @@ public static class Builder { private Locale locale = Locale.getDefault(); private ExecutionId executionId; private AtomicBoolean cancelled = new AtomicBoolean(false); + private boolean profileExecution; public Builder query(String query) { this.query = assertNotNull(query, () -> "query can't be null"); @@ -283,7 +291,7 @@ public Builder context(Object context) { return this; } - /** + /** * This will give you a builder of {@link GraphQLContext} and any values you set will be copied * into the underlying {@link GraphQLContext} of this execution input * @@ -360,6 +368,11 @@ public Builder dataLoaderRegistry(DataLoaderRegistry dataLoaderRegistry) { return this; } + public Builder profileExecution(boolean profileExecution) { + this.profileExecution = profileExecution; + return this; + } + public ExecutionInput build() { return new ExecutionInput(this); } diff --git a/src/main/java/graphql/GraphQL.java b/src/main/java/graphql/GraphQL.java index a279dab2fd..4f8e5d0341 100644 --- a/src/main/java/graphql/GraphQL.java +++ b/src/main/java/graphql/GraphQL.java @@ -420,6 +420,8 @@ public CompletableFuture executeAsync(UnaryOperator executeAsync(ExecutionInput executionInput) { + Profiler profiler = executionInput.isProfileExecution() ? new ProfilerImpl(executionInput.getGraphQLContext()) : Profiler.NO_OP; + profiler.start(); EngineRunningState engineRunningState = new EngineRunningState(executionInput); return engineRunningState.engineRun(() -> { ExecutionInput executionInputWithId = ensureInputHasId(executionInput); @@ -439,7 +441,7 @@ public CompletableFuture executeAsync(ExecutionInput executionI GraphQLSchema graphQLSchema = instrumentation.instrumentSchema(this.graphQLSchema, instrumentationParameters, instrumentationState); - CompletableFuture executionResult = parseValidateAndExecute(instrumentedExecutionInput, graphQLSchema, instrumentationState, engineRunningState); + CompletableFuture executionResult = parseValidateAndExecute(instrumentedExecutionInput, graphQLSchema, instrumentationState, engineRunningState, profiler); // // finish up instrumentation executionResult = executionResult.whenComplete(completeInstrumentationCtxCF(executionInstrumentation)); @@ -471,7 +473,7 @@ private ExecutionInput ensureInputHasId(ExecutionInput executionInput) { } - private CompletableFuture parseValidateAndExecute(ExecutionInput executionInput, GraphQLSchema graphQLSchema, InstrumentationState instrumentationState, EngineRunningState engineRunningState) { + private CompletableFuture parseValidateAndExecute(ExecutionInput executionInput, GraphQLSchema graphQLSchema, InstrumentationState instrumentationState, EngineRunningState engineRunningState, Profiler profiler) { AtomicReference executionInputRef = new AtomicReference<>(executionInput); Function computeFunction = transformedInput -> { // if they change the original query in the pre-parser, then we want to see it downstream from then on @@ -484,7 +486,7 @@ private CompletableFuture parseValidateAndExecute(ExecutionInpu return CompletableFuture.completedFuture(new ExecutionResultImpl(preparsedDocumentEntry.getErrors())); } try { - return execute(executionInputRef.get(), preparsedDocumentEntry.getDocument(), graphQLSchema, instrumentationState, engineRunningState); + return execute(executionInputRef.get(), preparsedDocumentEntry.getDocument(), graphQLSchema, instrumentationState, engineRunningState, profiler); } catch (AbortExecutionException e) { return CompletableFuture.completedFuture(e.toExecutionResult()); } @@ -548,13 +550,14 @@ private CompletableFuture execute(ExecutionInput executionInput Document document, GraphQLSchema graphQLSchema, InstrumentationState instrumentationState, - EngineRunningState engineRunningState + EngineRunningState engineRunningState, + Profiler profiler ) { Execution execution = new Execution(queryStrategy, mutationStrategy, subscriptionStrategy, instrumentation, valueUnboxer, responseMapFactory, doNotAutomaticallyDispatchDataLoader); ExecutionId executionId = executionInput.getExecutionId(); - return execution.execute(document, graphQLSchema, executionId, executionInput, instrumentationState, engineRunningState); + return execution.execute(document, graphQLSchema, executionId, executionInput, instrumentationState, engineRunningState, profiler); } } diff --git a/src/main/java/graphql/Profiler.java b/src/main/java/graphql/Profiler.java new file mode 100644 index 0000000000..ca5cb0d050 --- /dev/null +++ b/src/main/java/graphql/Profiler.java @@ -0,0 +1,31 @@ +package graphql; + +import graphql.execution.ResultPath; +import graphql.schema.DataFetcher; +import org.jspecify.annotations.NullMarked; + +@Internal +@NullMarked +public interface Profiler { + + + Profiler NO_OP = new Profiler() { + }; + + default void start() { + + } + + + default void rootFieldCount(int size) { + + } + + default void subSelectionCount(int size) { + + } + + default void fieldFetched(Object fetchedObject, DataFetcher dataFetcher, ResultPath path) { + + } +} diff --git a/src/main/java/graphql/ProfilerImpl.java b/src/main/java/graphql/ProfilerImpl.java new file mode 100644 index 0000000000..ade5119a09 --- /dev/null +++ b/src/main/java/graphql/ProfilerImpl.java @@ -0,0 +1,51 @@ +package graphql; + +import graphql.execution.ResultPath; +import graphql.schema.DataFetcher; +import org.jspecify.annotations.NullMarked; + +import java.util.Map; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.atomic.AtomicInteger; + +@Internal +@NullMarked +public class ProfilerImpl implements Profiler { + + volatile long startTime; + volatile int rootFieldCount; + + AtomicInteger propertyDataFetcherCount; + + final Map dataFetcherInvocationCount = new ConcurrentHashMap<>(); + + + final ProfilerResult profilerResult = new ProfilerResult(); + + public ProfilerImpl(GraphQLContext graphQLContext) { + graphQLContext.put(ProfilerResult.PROFILER_CONTEXT_KEY, profilerResult); + } + + @Override + public void start() { + startTime = System.nanoTime(); + } + + + @Override + public void rootFieldCount(int count) { + this.rootFieldCount = count; + } + + @Override + public void fieldFetched(Object fetchedObject, DataFetcher dataFetcher, ResultPath path) { + String key = String.join("/", path.getKeysOnly()); + profilerResult.addFieldFetched(key); + +// dataFetcherInvocationCount.compute(key, (k, v) -> v == null ? 1 : v + 1); +// +// if (dataFetcher instanceof PropertyDataFetcher) { +// propertyDataFetcherCount.incrementAndGet(); +// } + } +} diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java new file mode 100644 index 0000000000..dc98644400 --- /dev/null +++ b/src/main/java/graphql/ProfilerResult.java @@ -0,0 +1,37 @@ +package graphql; + +import java.util.Map; +import java.util.Set; +import java.util.concurrent.ConcurrentHashMap; + +@ExperimentalApi +public class ProfilerResult { + + public static String PROFILER_CONTEXT_KEY = "__GJ_PROFILER"; + + private int fieldCount; + + private int propertyDataFetcherCount; + + private final Set fieldsFetched = ConcurrentHashMap.newKeySet(); + + public static enum ResultType { + COMPLETABLE_FUTURE_COMPLETED, + COMPLETABLE_FUTURE_NOT_COMPLETED, + MATERIALIZED + + } + + private Map queryPathToResultType; + + + public void addFieldFetched(String fieldPath) { + fieldsFetched.add(fieldPath); + } + + public Set getFieldsFetched() { + return fieldsFetched; + } + + +} diff --git a/src/main/java/graphql/execution/Execution.java b/src/main/java/graphql/execution/Execution.java index f35854a188..25f78012f8 100644 --- a/src/main/java/graphql/execution/Execution.java +++ b/src/main/java/graphql/execution/Execution.java @@ -6,10 +6,10 @@ import graphql.ExecutionInput; import graphql.ExecutionResult; import graphql.ExecutionResultImpl; -import graphql.ExperimentalApi; import graphql.GraphQLContext; import graphql.GraphQLError; import graphql.Internal; +import graphql.Profiler; import graphql.execution.incremental.IncrementalCallState; import graphql.execution.instrumentation.Instrumentation; import graphql.execution.instrumentation.InstrumentationContext; @@ -37,7 +37,6 @@ import java.util.Collections; import java.util.List; import java.util.Map; -import java.util.Optional; import java.util.concurrent.CompletableFuture; import java.util.function.Supplier; @@ -77,7 +76,7 @@ public Execution(ExecutionStrategy queryStrategy, this.doNotAutomaticallyDispatchDataLoader = doNotAutomaticallyDispatchDataLoader; } - public CompletableFuture execute(Document document, GraphQLSchema graphQLSchema, ExecutionId executionId, ExecutionInput executionInput, InstrumentationState instrumentationState, EngineRunningState engineRunningState) { + public CompletableFuture execute(Document document, GraphQLSchema graphQLSchema, ExecutionId executionId, ExecutionInput executionInput, InstrumentationState instrumentationState, EngineRunningState engineRunningState, Profiler profiler) { NodeUtil.GetOperationResult getOperationResult; CoercedVariables coercedVariables; Supplier normalizedVariableValues; @@ -118,6 +117,7 @@ public CompletableFuture execute(Document document, GraphQLSche .executionInput(executionInput) .propagapropagateErrorsOnNonNullContractFailureeErrors(propagateErrorsOnNonNullContractFailure) .engineRunningState(engineRunningState) + .profiler(profiler) .build(); executionContext.getGraphQLContext().put(ResultNodesInfo.RESULT_NODES_INFO, executionContext.getResultNodesInfo()); diff --git a/src/main/java/graphql/execution/ExecutionContext.java b/src/main/java/graphql/execution/ExecutionContext.java index a22f8fd665..bd528b4255 100644 --- a/src/main/java/graphql/execution/ExecutionContext.java +++ b/src/main/java/graphql/execution/ExecutionContext.java @@ -9,6 +9,7 @@ import graphql.GraphQLContext; import graphql.GraphQLError; import graphql.Internal; +import graphql.Profiler; import graphql.PublicApi; import graphql.collect.ImmutableKit; import graphql.execution.incremental.IncrementalCallState; @@ -29,7 +30,6 @@ import java.util.Locale; import java.util.Map; import java.util.Set; -import java.util.concurrent.atomic.AtomicInteger; import java.util.concurrent.atomic.AtomicReference; import java.util.function.Consumer; import java.util.function.Supplier; @@ -67,14 +67,14 @@ public class ExecutionContext { private final Supplier queryTree; private final boolean propagateErrorsOnNonNullContractFailure; - private final AtomicInteger isRunning = new AtomicInteger(0); - // this is modified after creation so it needs to be volatile to ensure visibility across Threads private volatile DataLoaderDispatchStrategy dataLoaderDispatcherStrategy = DataLoaderDispatchStrategy.NO_OP; private final ResultNodesInfo resultNodesInfo = new ResultNodesInfo(); private final EngineRunningState engineRunningState; + private final Profiler profiler; + ExecutionContext(ExecutionContextBuilder builder) { this.graphQLSchema = builder.graphQLSchema; this.executionId = builder.executionId; @@ -102,6 +102,7 @@ public class ExecutionContext { this.queryTree = FpKit.interThreadMemoize(() -> ExecutableNormalizedOperationFactory.createExecutableNormalizedOperation(graphQLSchema, operationDefinition, fragmentsByName, coercedVariables)); this.propagateErrorsOnNonNullContractFailure = builder.propagateErrorsOnNonNullContractFailure; this.engineRunningState = builder.engineRunningState; + this.profiler = builder.profiler; } public ExecutionId getExecutionId() { @@ -376,4 +377,10 @@ public boolean hasIncrementalSupport() { public EngineRunningState getEngineRunningState() { return engineRunningState; } + + + @Internal + public Profiler getProfiler() { + return profiler; + } } diff --git a/src/main/java/graphql/execution/ExecutionContextBuilder.java b/src/main/java/graphql/execution/ExecutionContextBuilder.java index 53dce77981..9ac2ebbab1 100644 --- a/src/main/java/graphql/execution/ExecutionContextBuilder.java +++ b/src/main/java/graphql/execution/ExecutionContextBuilder.java @@ -8,6 +8,7 @@ import graphql.GraphQLContext; import graphql.GraphQLError; import graphql.Internal; +import graphql.Profiler; import graphql.collect.ImmutableKit; import graphql.execution.instrumentation.Instrumentation; import graphql.execution.instrumentation.InstrumentationState; @@ -53,6 +54,7 @@ public class ExecutionContextBuilder { boolean propagateErrorsOnNonNullContractFailure = true; EngineRunningState engineRunningState; ResponseMapFactory responseMapFactory = ResponseMapFactory.DEFAULT; + Profiler profiler; /** * @return a new builder of {@link graphql.execution.ExecutionContext}s @@ -102,6 +104,7 @@ public ExecutionContextBuilder() { propagateErrorsOnNonNullContractFailure = other.propagateErrorsOnNonNullContractFailure(); engineRunningState = other.getEngineRunningState(); responseMapFactory = other.getResponseMapFactory(); + profiler = other.getProfiler(); } public ExecutionContextBuilder instrumentation(Instrumentation instrumentation) { @@ -253,4 +256,9 @@ public ExecutionContextBuilder engineRunningState(EngineRunningState engineRunni this.engineRunningState = engineRunningState; return this; } + + public ExecutionContextBuilder profiler(Profiler profiler) { + this.profiler = profiler; + return this; + } } diff --git a/src/main/java/graphql/execution/ExecutionStrategy.java b/src/main/java/graphql/execution/ExecutionStrategy.java index 355f13106b..7d9a9e54d9 100644 --- a/src/main/java/graphql/execution/ExecutionStrategy.java +++ b/src/main/java/graphql/execution/ExecutionStrategy.java @@ -5,7 +5,6 @@ import graphql.EngineRunningState; import graphql.ExecutionResult; import graphql.ExecutionResultImpl; -import graphql.ExperimentalApi; import graphql.GraphQLError; import graphql.Internal; import graphql.PublicSpi; @@ -50,7 +49,6 @@ import java.util.Collections; import java.util.List; import java.util.Map; -import java.util.Optional; import java.util.OptionalInt; import java.util.concurrent.CompletableFuture; import java.util.concurrent.CompletionException; @@ -400,7 +398,6 @@ private Object fetchField(GraphQLFieldDefinition fieldDef, ExecutionContext exec } MergedField field = parameters.getField(); - String pathString = parameters.getPath().toString(); GraphQLObjectType parentType = (GraphQLObjectType) parameters.getExecutionStepInfo().getUnwrappedNonNullType(); // if the DF (like PropertyDataFetcher) does not use the arguments or execution step info then dont build any @@ -498,6 +495,7 @@ private Object invokeDataFetcher(ExecutionContext executionContext, ExecutionStr } else { fetchedValueRaw = dataFetcher.get(dataFetchingEnvironment.get()); } + executionContext.getProfiler().fieldFetched(fetchedValueRaw, dataFetcher, parameters.getPath()); fetchedValue = Async.toCompletableFutureOrMaterializedObject(fetchedValueRaw); } catch (Exception e) { fetchedValue = Async.exceptionallyCompletedFuture(e); diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy new file mode 100644 index 0000000000..6904a8b335 --- /dev/null +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -0,0 +1,38 @@ +package graphql + +import graphql.schema.DataFetcher +import graphql.schema.DataFetchingEnvironment +import spock.lang.Specification + +class ProfilerTest extends Specification { + + + def "simple query"() { + given: + def sdl = ''' + type Query { + hello: String + } + ''' + def schema = TestUtil.schema(sdl, [Query: [ + hello: { DataFetchingEnvironment dfe -> return "world" } as DataFetcher + ]]) + def graphql = GraphQL.newGraphQL(schema).build(); + + ExecutionInput ei = ExecutionInput.newExecutionInput() + .query("{ hello }") + .profileExecution(true) + .build() + + when: + def result = graphql.execute(ei) + def profilerResult = ei.getGraphQLContext().get(ProfilerResult.PROFILER_CONTEXT_KEY) as ProfilerResult + + then: + result.getData() == [hello: "world"] + + then: + profilerResult.getFieldsFetched() == ["hello"] as Set + + } +} diff --git a/src/test/groovy/graphql/execution/AsyncExecutionStrategyTest.groovy b/src/test/groovy/graphql/execution/AsyncExecutionStrategyTest.groovy index 9d99fbbfba..58baa41ece 100644 --- a/src/test/groovy/graphql/execution/AsyncExecutionStrategyTest.groovy +++ b/src/test/groovy/graphql/execution/AsyncExecutionStrategyTest.groovy @@ -5,6 +5,7 @@ import graphql.ErrorType import graphql.ExecutionInput import graphql.ExecutionResult import graphql.GraphQLContext +import graphql.Profiler import graphql.execution.instrumentation.ExecutionStrategyInstrumentationContext import graphql.execution.instrumentation.InstrumentationState import graphql.execution.instrumentation.SimplePerformantInstrumentation @@ -112,6 +113,7 @@ abstract class AsyncExecutionStrategyTest extends Specification { .executionInput(ExecutionInput.newExecutionInput("{}").build()) .locale(Locale.getDefault()) .engineRunningState(new EngineRunningState()) + .profiler(Profiler.NO_OP) .build() ExecutionStrategyParameters executionStrategyParameters = ExecutionStrategyParameters .newParameters() @@ -156,6 +158,7 @@ abstract class AsyncExecutionStrategyTest extends Specification { .graphQLContext(graphqlContextMock) .executionInput(ExecutionInput.newExecutionInput("{}").build()) .engineRunningState(new EngineRunningState()) + .profiler(Profiler.NO_OP) .build() ExecutionStrategyParameters executionStrategyParameters = ExecutionStrategyParameters .newParameters() @@ -202,6 +205,7 @@ abstract class AsyncExecutionStrategyTest extends Specification { .executionInput(ExecutionInput.newExecutionInput("{}").build()) .engineRunningState(new EngineRunningState()) .locale(Locale.getDefault()) + .profiler(Profiler.NO_OP) .build() ExecutionStrategyParameters executionStrategyParameters = ExecutionStrategyParameters .newParameters() @@ -247,6 +251,7 @@ abstract class AsyncExecutionStrategyTest extends Specification { .graphQLContext(graphqlContextMock) .executionInput(ExecutionInput.newExecutionInput("{}").build()) .engineRunningState(new EngineRunningState()) + .profiler(Profiler.NO_OP) .build() ExecutionStrategyParameters executionStrategyParameters = ExecutionStrategyParameters .newParameters() @@ -290,6 +295,7 @@ abstract class AsyncExecutionStrategyTest extends Specification { .executionInput(ExecutionInput.newExecutionInput("{}").build()) .locale(Locale.getDefault()) .engineRunningState(new EngineRunningState()) + .profiler(Profiler.NO_OP) .instrumentation(new SimplePerformantInstrumentation() { @Override diff --git a/src/test/groovy/graphql/execution/AsyncSerialExecutionStrategyTest.groovy b/src/test/groovy/graphql/execution/AsyncSerialExecutionStrategyTest.groovy index 937c99c705..95cf98b931 100644 --- a/src/test/groovy/graphql/execution/AsyncSerialExecutionStrategyTest.groovy +++ b/src/test/groovy/graphql/execution/AsyncSerialExecutionStrategyTest.groovy @@ -3,6 +3,7 @@ package graphql.execution import graphql.EngineRunningState import graphql.ExecutionInput import graphql.GraphQLContext +import graphql.Profiler import graphql.execution.instrumentation.SimplePerformantInstrumentation import graphql.language.Field import graphql.language.OperationDefinition @@ -110,6 +111,7 @@ class AsyncSerialExecutionStrategyTest extends Specification { .graphQLContext(GraphQLContext.getDefault()) .executionInput(ExecutionInput.newExecutionInput("{}").build()) .engineRunningState(new EngineRunningState()) + .profiler(Profiler.NO_OP) .build() ExecutionStrategyParameters executionStrategyParameters = ExecutionStrategyParameters .newParameters() @@ -159,6 +161,7 @@ class AsyncSerialExecutionStrategyTest extends Specification { .graphQLContext(GraphQLContext.getDefault()) .executionInput(ExecutionInput.newExecutionInput("{}").build()) .engineRunningState(new EngineRunningState()) + .profiler(Profiler.NO_OP) .build() ExecutionStrategyParameters executionStrategyParameters = ExecutionStrategyParameters .newParameters() diff --git a/src/test/groovy/graphql/execution/ExecutionStrategyTest.groovy b/src/test/groovy/graphql/execution/ExecutionStrategyTest.groovy index a8de454c06..0a05a5d04b 100644 --- a/src/test/groovy/graphql/execution/ExecutionStrategyTest.groovy +++ b/src/test/groovy/graphql/execution/ExecutionStrategyTest.groovy @@ -7,6 +7,7 @@ import graphql.ExecutionInput import graphql.ExecutionResult import graphql.GraphQLContext import graphql.GraphqlErrorBuilder +import graphql.Profiler import graphql.Scalars import graphql.SerializationError import graphql.StarWarsSchema @@ -86,6 +87,7 @@ class ExecutionStrategyTest extends Specification { .locale(Locale.getDefault()) .valueUnboxer(ValueUnboxer.DEFAULT) .engineRunningState(new EngineRunningState()) + .profiler(Profiler.NO_OP) new ExecutionContext(builder) } diff --git a/src/test/groovy/graphql/execution/ExecutionTest.groovy b/src/test/groovy/graphql/execution/ExecutionTest.groovy index 1557d94d29..dadc2ff576 100644 --- a/src/test/groovy/graphql/execution/ExecutionTest.groovy +++ b/src/test/groovy/graphql/execution/ExecutionTest.groovy @@ -5,6 +5,7 @@ import graphql.ExecutionInput import graphql.ExecutionResult import graphql.ExecutionResultImpl import graphql.MutationSchema +import graphql.Profiler import graphql.execution.instrumentation.InstrumentationState import graphql.execution.instrumentation.SimplePerformantInstrumentation import graphql.execution.instrumentation.parameters.InstrumentationExecutionParameters @@ -52,7 +53,7 @@ class ExecutionTest extends Specification { def document = parser.parseDocument(query) when: - execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput)) + execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput), Profiler.NO_OP) then: queryStrategy.execute == 1 @@ -72,7 +73,7 @@ class ExecutionTest extends Specification { def document = parser.parseDocument(query) when: - execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput)) + execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput), Profiler.NO_OP) then: queryStrategy.execute == 0 @@ -92,7 +93,7 @@ class ExecutionTest extends Specification { def document = parser.parseDocument(query) when: - execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput)) + execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput), Profiler.NO_OP) then: queryStrategy.execute == 0 @@ -129,7 +130,7 @@ class ExecutionTest extends Specification { when: - execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput)) + execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput), Profiler.NO_OP) then: queryStrategy.execute == 0 diff --git a/src/test/groovy/graphql/execution/instrumentation/fieldvalidation/FieldValidationTest.groovy b/src/test/groovy/graphql/execution/instrumentation/fieldvalidation/FieldValidationTest.groovy index 67712b7fe9..7dddb89944 100644 --- a/src/test/groovy/graphql/execution/instrumentation/fieldvalidation/FieldValidationTest.groovy +++ b/src/test/groovy/graphql/execution/instrumentation/fieldvalidation/FieldValidationTest.groovy @@ -5,6 +5,7 @@ import graphql.ExecutionInput import graphql.ExecutionResult import graphql.GraphQL import graphql.GraphQLError +import graphql.Profiler import graphql.TestUtil import graphql.execution.AbortExecutionException import graphql.execution.AsyncExecutionStrategy @@ -310,7 +311,7 @@ class FieldValidationTest extends Specification { def execution = new Execution(strategy, strategy, strategy, instrumentation, ValueUnboxer.DEFAULT, ResponseMapFactory.DEFAULT, false) def executionInput = ExecutionInput.newExecutionInput().query(query).variables(variables).build() - execution.execute(document, schema, ExecutionId.generate(), executionInput, null, new EngineRunningState()) + execution.execute(document, schema, ExecutionId.generate(), executionInput, null, new EngineRunningState(), Profiler.NO_OP) } def "test graphql from end to end with chained instrumentation"() { From cc1de5ea33d17e43112cd6d4b22eedccac830e58 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Mon, 19 May 2025 22:09:23 +1000 Subject: [PATCH 02/25] progress --- src/main/java/graphql/ProfilerImpl.java | 31 ++++------- src/main/java/graphql/ProfilerResult.java | 61 +++++++++++++++++++-- src/test/groovy/graphql/ProfilerTest.groovy | 41 +++++++++++++- 3 files changed, 107 insertions(+), 26 deletions(-) diff --git a/src/main/java/graphql/ProfilerImpl.java b/src/main/java/graphql/ProfilerImpl.java index ade5119a09..47182f998b 100644 --- a/src/main/java/graphql/ProfilerImpl.java +++ b/src/main/java/graphql/ProfilerImpl.java @@ -2,22 +2,15 @@ import graphql.execution.ResultPath; import graphql.schema.DataFetcher; +import graphql.schema.PropertyDataFetcher; +import graphql.schema.SingletonPropertyDataFetcher; import org.jspecify.annotations.NullMarked; -import java.util.Map; -import java.util.concurrent.ConcurrentHashMap; -import java.util.concurrent.atomic.AtomicInteger; - @Internal @NullMarked public class ProfilerImpl implements Profiler { volatile long startTime; - volatile int rootFieldCount; - - AtomicInteger propertyDataFetcherCount; - - final Map dataFetcherInvocationCount = new ConcurrentHashMap<>(); final ProfilerResult profilerResult = new ProfilerResult(); @@ -31,21 +24,17 @@ public void start() { startTime = System.nanoTime(); } - - @Override - public void rootFieldCount(int count) { - this.rootFieldCount = count; - } - @Override public void fieldFetched(Object fetchedObject, DataFetcher dataFetcher, ResultPath path) { String key = String.join("/", path.getKeysOnly()); profilerResult.addFieldFetched(key); - -// dataFetcherInvocationCount.compute(key, (k, v) -> v == null ? 1 : v + 1); -// -// if (dataFetcher instanceof PropertyDataFetcher) { -// propertyDataFetcherCount.incrementAndGet(); -// } + profilerResult.incrementDataFetcherInvocationCount(key); + ProfilerResult.DataFetcherType dataFetcherType; + if (dataFetcher instanceof PropertyDataFetcher || dataFetcher instanceof SingletonPropertyDataFetcher) { + dataFetcherType = ProfilerResult.DataFetcherType.PROPERTY_DATA_FETCHER; + } else { + dataFetcherType = ProfilerResult.DataFetcherType.CUSTOM; + } + profilerResult.setDataFetcherType(key, dataFetcherType); } } diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index dc98644400..04aa28293f 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -1,21 +1,30 @@ package graphql; +import java.util.LinkedHashSet; import java.util.Map; import java.util.Set; import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.atomic.AtomicInteger; @ExperimentalApi public class ProfilerResult { public static String PROFILER_CONTEXT_KEY = "__GJ_PROFILER"; - private int fieldCount; + private final AtomicInteger totalDataFetcherInvocations = new AtomicInteger(); + private final AtomicInteger totalPropertyDataFetcherInvocations = new AtomicInteger(); - private int propertyDataFetcherCount; private final Set fieldsFetched = ConcurrentHashMap.newKeySet(); + private final Map dataFetcherInvocationCount = new ConcurrentHashMap<>(); + private final Map dataFetcherTypeMap = new ConcurrentHashMap<>(); - public static enum ResultType { + public enum DataFetcherType { + PROPERTY_DATA_FETCHER, + CUSTOM + } + + public enum ResultType { COMPLETABLE_FUTURE_COMPLETED, COMPLETABLE_FUTURE_NOT_COMPLETED, MATERIALIZED @@ -24,14 +33,58 @@ public static enum ResultType { private Map queryPathToResultType; + void setDataFetcherType(String key, DataFetcherType dataFetcherType) { + dataFetcherTypeMap.putIfAbsent(key, dataFetcherType); + totalDataFetcherInvocations.incrementAndGet(); + if (dataFetcherType == DataFetcherType.PROPERTY_DATA_FETCHER) { + totalPropertyDataFetcherInvocations.incrementAndGet(); + } + } + + void incrementDataFetcherInvocationCount(String key) { + dataFetcherInvocationCount.compute(key, (k, v) -> v == null ? 1 : v + 1); + } - public void addFieldFetched(String fieldPath) { + void addFieldFetched(String fieldPath) { fieldsFetched.add(fieldPath); } + public Set getFieldsFetched() { return fieldsFetched; } + public Set getCustomDataFetcherFields() { + Set result = new LinkedHashSet<>(fieldsFetched); + for (String field : fieldsFetched) { + if (dataFetcherTypeMap.get(field) == DataFetcherType.CUSTOM) { + result.add(field); + } + } + return result; + } + + public Set getPropertyDataFetcherFields() { + Set result = new LinkedHashSet<>(fieldsFetched); + for (String field : fieldsFetched) { + if (dataFetcherTypeMap.get(field) == DataFetcherType.PROPERTY_DATA_FETCHER) { + result.add(field); + } + } + return result; + } + + + public int getTotalDataFetcherInvocations() { + return totalDataFetcherInvocations.get(); + } + + public int getTotalPropertyDataFetcherInvocations() { + return totalPropertyDataFetcherInvocations.get(); + } + + public int getTotalCustomDataFetcherInvocations() { + return totalDataFetcherInvocations.get() - totalPropertyDataFetcherInvocations.get(); + } } diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index 6904a8b335..b314e8bba2 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -7,7 +7,7 @@ import spock.lang.Specification class ProfilerTest extends Specification { - def "simple query"() { + def "one field"() { given: def sdl = ''' type Query { @@ -35,4 +35,43 @@ class ProfilerTest extends Specification { profilerResult.getFieldsFetched() == ["hello"] as Set } + + def "two DF with list"() { + given: + def sdl = ''' + type Query { + foo: [Foo] + } + type Foo { + id: String + bar: String + } + ''' + def schema = TestUtil.schema(sdl, [ + Query: [ + foo: { DataFetchingEnvironment dfe -> return [[id: "1"], [id: "2"], [id: "3"]] } as DataFetcher], + Foo : [ + bar: { DataFetchingEnvironment dfe -> dfe.source.id } as DataFetcher + ]]) + def graphql = GraphQL.newGraphQL(schema).build(); + + ExecutionInput ei = ExecutionInput.newExecutionInput() + .query("{ foo { id bar } }") + .profileExecution(true) + .build() + + when: + def result = graphql.execute(ei) + def profilerResult = ei.getGraphQLContext().get(ProfilerResult.PROFILER_CONTEXT_KEY) as ProfilerResult + + then: + result.getData() == [foo: [[id: "1", bar: "1"], [id: "2", bar: "2"], [id: "3", bar: "3"]]] + + then: + profilerResult.getFieldsFetched() == ["foo", "foo/bar", "foo/id"] as Set + profilerResult.getTotalDataFetcherInvocations() == 7 + profilerResult.getTotalCustomDataFetcherInvocations() == 4 + profilerResult.getTotalPropertyDataFetcherInvocations() == 3 + } + } From eef80ecbb53eb9b2f78f463190d6109d33f40a20 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Tue, 20 May 2025 10:34:50 +1000 Subject: [PATCH 03/25] track running time --- src/main/java/graphql/EngineRunningState.java | 7 ++- src/main/java/graphql/GraphQL.java | 4 +- src/main/java/graphql/Profiler.java | 11 ++++ src/main/java/graphql/ProfilerImpl.java | 45 ++++++++++++++- src/main/java/graphql/ProfilerResult.java | 55 ++++++++++++++++++- src/test/groovy/graphql/ProfilerTest.groovy | 52 ++++++++++++++++++ .../graphql/execution/ExecutionTest.groovy | 8 +-- 7 files changed, 167 insertions(+), 15 deletions(-) diff --git a/src/main/java/graphql/EngineRunningState.java b/src/main/java/graphql/EngineRunningState.java index 1bbbbe0754..9b901f2367 100644 --- a/src/main/java/graphql/EngineRunningState.java +++ b/src/main/java/graphql/EngineRunningState.java @@ -42,10 +42,11 @@ public EngineRunningState() { this.executionId = null; } - public EngineRunningState(ExecutionInput executionInput) { + public EngineRunningState(ExecutionInput executionInput, Profiler profiler) { EngineRunningObserver engineRunningObserver = executionInput.getGraphQLContext().get(EngineRunningObserver.ENGINE_RUNNING_OBSERVER_KEY); - if (engineRunningObserver != null) { - this.engineRunningObserver = engineRunningObserver; + EngineRunningObserver wrappedObserver = profiler.wrapEngineRunningObserver(engineRunningObserver); + if (wrappedObserver != null) { + this.engineRunningObserver = wrappedObserver; this.graphQLContext = executionInput.getGraphQLContext(); this.executionId = executionInput.getExecutionId(); } else { diff --git a/src/main/java/graphql/GraphQL.java b/src/main/java/graphql/GraphQL.java index 4f8e5d0341..55121a1e6e 100644 --- a/src/main/java/graphql/GraphQL.java +++ b/src/main/java/graphql/GraphQL.java @@ -421,10 +421,10 @@ public CompletableFuture executeAsync(UnaryOperator executeAsync(ExecutionInput executionInput) { Profiler profiler = executionInput.isProfileExecution() ? new ProfilerImpl(executionInput.getGraphQLContext()) : Profiler.NO_OP; - profiler.start(); - EngineRunningState engineRunningState = new EngineRunningState(executionInput); + EngineRunningState engineRunningState = new EngineRunningState(executionInput, profiler); return engineRunningState.engineRun(() -> { ExecutionInput executionInputWithId = ensureInputHasId(executionInput); + profiler.setExecutionId(executionInputWithId.getExecutionId()); engineRunningState.updateExecutionId(executionInputWithId.getExecutionId()); CompletableFuture instrumentationStateCF = instrumentation.createStateAsync(new InstrumentationCreateStateParameters(this.graphQLSchema, executionInputWithId)); diff --git a/src/main/java/graphql/Profiler.java b/src/main/java/graphql/Profiler.java index ca5cb0d050..1732a76abf 100644 --- a/src/main/java/graphql/Profiler.java +++ b/src/main/java/graphql/Profiler.java @@ -1,8 +1,11 @@ package graphql; +import graphql.execution.EngineRunningObserver; +import graphql.execution.ExecutionId; import graphql.execution.ResultPath; import graphql.schema.DataFetcher; import org.jspecify.annotations.NullMarked; +import org.jspecify.annotations.Nullable; @Internal @NullMarked @@ -25,7 +28,15 @@ default void subSelectionCount(int size) { } + default void setExecutionId(ExecutionId executionId) { + + } + default void fieldFetched(Object fetchedObject, DataFetcher dataFetcher, ResultPath path) { } + + default @Nullable EngineRunningObserver wrapEngineRunningObserver(EngineRunningObserver engineRunningObserver) { + return engineRunningObserver; + } } diff --git a/src/main/java/graphql/ProfilerImpl.java b/src/main/java/graphql/ProfilerImpl.java index 47182f998b..383ecedbc5 100644 --- a/src/main/java/graphql/ProfilerImpl.java +++ b/src/main/java/graphql/ProfilerImpl.java @@ -1,16 +1,23 @@ package graphql; +import graphql.execution.EngineRunningObserver; +import graphql.execution.ExecutionId; import graphql.execution.ResultPath; import graphql.schema.DataFetcher; import graphql.schema.PropertyDataFetcher; import graphql.schema.SingletonPropertyDataFetcher; import org.jspecify.annotations.NullMarked; +import java.util.concurrent.atomic.AtomicLong; + @Internal @NullMarked public class ProfilerImpl implements Profiler { - volatile long startTime; + private volatile long startTime; + private volatile long endTime; + private volatile long lastStartTime; + private final AtomicLong engineTotalRunningTime = new AtomicLong(); final ProfilerResult profilerResult = new ProfilerResult(); @@ -20,8 +27,8 @@ public ProfilerImpl(GraphQLContext graphQLContext) { } @Override - public void start() { - startTime = System.nanoTime(); + public void setExecutionId(ExecutionId executionId) { + profilerResult.setExecutionId(executionId); } @Override @@ -37,4 +44,36 @@ public void fieldFetched(Object fetchedObject, DataFetcher dataFetcher, Resul } profilerResult.setDataFetcherType(key, dataFetcherType); } + + @Override + public EngineRunningObserver wrapEngineRunningObserver(EngineRunningObserver engineRunningObserver) { + // nothing to wrap here + return new EngineRunningObserver() { + @Override + public void runningStateChanged(ExecutionId executionId, GraphQLContext graphQLContext, RunningState runningState) { + runningStateChangedImpl(executionId, graphQLContext, runningState); + if (engineRunningObserver != null) { + engineRunningObserver.runningStateChanged(executionId, graphQLContext, runningState); + } + } + }; + } + + private void runningStateChangedImpl(ExecutionId executionId, GraphQLContext graphQLContext, EngineRunningObserver.RunningState runningState) { + long now = System.nanoTime(); + if (runningState == EngineRunningObserver.RunningState.RUNNING_START) { + startTime = now; + lastStartTime = startTime; + } else if (runningState == EngineRunningObserver.RunningState.NOT_RUNNING_FINISH) { + endTime = now; + engineTotalRunningTime.set(engineTotalRunningTime.get() + (endTime - lastStartTime)); + profilerResult.setTimes(startTime, endTime, engineTotalRunningTime.get()); + } else if (runningState == EngineRunningObserver.RunningState.RUNNING) { + lastStartTime = now; + } else if (runningState == EngineRunningObserver.RunningState.NOT_RUNNING) { + engineTotalRunningTime.set(engineTotalRunningTime.get() + (now - lastStartTime)); + } else { + Assert.assertShouldNeverHappen(); + } + } } diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index 04aa28293f..0faadec715 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -1,5 +1,7 @@ package graphql; +import graphql.execution.ExecutionId; + import java.util.LinkedHashSet; import java.util.Map; import java.util.Set; @@ -9,16 +11,22 @@ @ExperimentalApi public class ProfilerResult { - public static String PROFILER_CONTEXT_KEY = "__GJ_PROFILER"; + public static final String PROFILER_CONTEXT_KEY = "__GJ_PROFILER"; + + private volatile ExecutionId executionId; + private long startTime; + private long endTime; + private long engineTotalRunningTime; + private final Set fieldsFetched = ConcurrentHashMap.newKeySet(); private final AtomicInteger totalDataFetcherInvocations = new AtomicInteger(); private final AtomicInteger totalPropertyDataFetcherInvocations = new AtomicInteger(); - private final Set fieldsFetched = ConcurrentHashMap.newKeySet(); private final Map dataFetcherInvocationCount = new ConcurrentHashMap<>(); private final Map dataFetcherTypeMap = new ConcurrentHashMap<>(); + public enum DataFetcherType { PROPERTY_DATA_FETCHER, CUSTOM @@ -31,7 +39,8 @@ public enum ResultType { } - private Map queryPathToResultType; + + // setters are package private to prevent exposure void setDataFetcherType(String key, DataFetcherType dataFetcherType) { dataFetcherTypeMap.putIfAbsent(key, dataFetcherType); @@ -49,6 +58,16 @@ void addFieldFetched(String fieldPath) { fieldsFetched.add(fieldPath); } + void setExecutionId(ExecutionId executionId) { + this.executionId = executionId; + } + + void setTimes(long startTime, long endTime, long engineTotalRunningTime) { + this.startTime = startTime; + this.endTime = endTime; + this.engineTotalRunningTime = engineTotalRunningTime; + } + public Set getFieldsFetched() { return fieldsFetched; @@ -87,4 +106,34 @@ public int getTotalCustomDataFetcherInvocations() { return totalDataFetcherInvocations.get() - totalPropertyDataFetcherInvocations.get(); } + public long getStartTime() { + return startTime; + } + + public long getEndTime() { + return endTime; + } + + public long getEngineTotalRunningTime() { + return engineTotalRunningTime; + } + + public long getTotalExecutionTime() { + return endTime - startTime; + } + + @Override + public String toString() { + return "ProfilerResult{" + + "executionId=" + executionId + + ", startTime=" + startTime + + ", endTime=" + endTime + + ", engineTotalRunningTime=" + engineTotalRunningTime + + ", fieldsFetched=" + fieldsFetched + + ", totalDataFetcherInvocations=" + totalDataFetcherInvocations + + ", totalPropertyDataFetcherInvocations=" + totalPropertyDataFetcherInvocations + + ", dataFetcherInvocationCount=" + dataFetcherInvocationCount + + ", dataFetcherTypeMap=" + dataFetcherTypeMap + + '}'; + } } diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index b314e8bba2..288847b371 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -4,6 +4,9 @@ import graphql.schema.DataFetcher import graphql.schema.DataFetchingEnvironment import spock.lang.Specification +import java.time.Duration +import java.util.concurrent.CompletableFuture + class ProfilerTest extends Specification { @@ -74,4 +77,53 @@ class ProfilerTest extends Specification { profilerResult.getTotalPropertyDataFetcherInvocations() == 3 } + def "records timing"() { + given: + def sdl = ''' + type Query { + foo: Foo + } + type Foo { + id: String + } + ''' + def schema = TestUtil.schema(sdl, [ + Query: [ + foo: { DataFetchingEnvironment dfe -> + return CompletableFuture.supplyAsync { + Thread.sleep(500) + "1" + } + } as DataFetcher], + Foo : [ + id: { DataFetchingEnvironment dfe -> + return CompletableFuture.supplyAsync { + Thread.sleep(500) + dfe.source + } + } as DataFetcher + ]]) + def graphql = GraphQL.newGraphQL(schema).build(); + + ExecutionInput ei = ExecutionInput.newExecutionInput() + .query("{ foo { id } }") + .profileExecution(true) + .build() + + when: + def result = graphql.execute(ei) + def profilerResult = ei.getGraphQLContext().get(ProfilerResult.PROFILER_CONTEXT_KEY) as ProfilerResult + + then: + result.getData() == [foo: [id: "1"]] + // the total execution time must be more than 1 second, + // the engine should take less than 500ms + profilerResult.getTotalExecutionTime() > Duration.ofSeconds(1).toNanos() + profilerResult.getEngineTotalRunningTime() > Duration.ofMillis(1).toNanos() + profilerResult.getEngineTotalRunningTime() < Duration.ofMillis(500).toNanos() + + + } + + } diff --git a/src/test/groovy/graphql/execution/ExecutionTest.groovy b/src/test/groovy/graphql/execution/ExecutionTest.groovy index dadc2ff576..8027d9b35b 100644 --- a/src/test/groovy/graphql/execution/ExecutionTest.groovy +++ b/src/test/groovy/graphql/execution/ExecutionTest.groovy @@ -53,7 +53,7 @@ class ExecutionTest extends Specification { def document = parser.parseDocument(query) when: - execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput), Profiler.NO_OP) + execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput, Profiler.NO_OP), Profiler.NO_OP) then: queryStrategy.execute == 1 @@ -73,7 +73,7 @@ class ExecutionTest extends Specification { def document = parser.parseDocument(query) when: - execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput), Profiler.NO_OP) + execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput, Profiler.NO_OP), Profiler.NO_OP) then: queryStrategy.execute == 0 @@ -93,7 +93,7 @@ class ExecutionTest extends Specification { def document = parser.parseDocument(query) when: - execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput), Profiler.NO_OP) + execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput, Profiler.NO_OP), Profiler.NO_OP) then: queryStrategy.execute == 0 @@ -130,7 +130,7 @@ class ExecutionTest extends Specification { when: - execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput), Profiler.NO_OP) + execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput, Profiler.NO_OP), Profiler.NO_OP) then: queryStrategy.execute == 0 From 15cf6428f1a23ae2be7d5de418c754c85838b3aa Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Tue, 20 May 2025 10:51:56 +1000 Subject: [PATCH 04/25] tracking datafetcher result types --- src/main/java/graphql/ProfilerImpl.java | 17 ++++++- src/main/java/graphql/ProfilerResult.java | 14 +++++- src/test/groovy/graphql/ProfilerTest.groovy | 49 ++++++++++++++++++++- 3 files changed, 76 insertions(+), 4 deletions(-) diff --git a/src/main/java/graphql/ProfilerImpl.java b/src/main/java/graphql/ProfilerImpl.java index 383ecedbc5..7a51dc86fc 100644 --- a/src/main/java/graphql/ProfilerImpl.java +++ b/src/main/java/graphql/ProfilerImpl.java @@ -8,6 +8,7 @@ import graphql.schema.SingletonPropertyDataFetcher; import org.jspecify.annotations.NullMarked; +import java.util.concurrent.CompletableFuture; import java.util.concurrent.atomic.AtomicLong; @Internal @@ -33,7 +34,7 @@ public void setExecutionId(ExecutionId executionId) { @Override public void fieldFetched(Object fetchedObject, DataFetcher dataFetcher, ResultPath path) { - String key = String.join("/", path.getKeysOnly()); + String key = "/" + String.join("/", path.getKeysOnly()); profilerResult.addFieldFetched(key); profilerResult.incrementDataFetcherInvocationCount(key); ProfilerResult.DataFetcherType dataFetcherType; @@ -41,7 +42,21 @@ public void fieldFetched(Object fetchedObject, DataFetcher dataFetcher, Resul dataFetcherType = ProfilerResult.DataFetcherType.PROPERTY_DATA_FETCHER; } else { dataFetcherType = ProfilerResult.DataFetcherType.CUSTOM; + // we only record the type of the result if it is not a PropertyDataFetcher + ProfilerResult.DataFetcherResultType dataFetcherResultType; + if (fetchedObject instanceof CompletableFuture) { + CompletableFuture completableFuture = (CompletableFuture) fetchedObject; + if (completableFuture.isDone()) { + dataFetcherResultType = ProfilerResult.DataFetcherResultType.COMPLETABLE_FUTURE_COMPLETED; + } else { + dataFetcherResultType = ProfilerResult.DataFetcherResultType.COMPLETABLE_FUTURE_NOT_COMPLETED; + } + } else { + dataFetcherResultType = ProfilerResult.DataFetcherResultType.MATERIALIZED; + } + profilerResult.setDataFetcherResultType(path.toString(), dataFetcherResultType); } + profilerResult.setDataFetcherType(key, dataFetcherType); } diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index 0faadec715..95e25f3371 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -26,13 +26,16 @@ public class ProfilerResult { private final Map dataFetcherInvocationCount = new ConcurrentHashMap<>(); private final Map dataFetcherTypeMap = new ConcurrentHashMap<>(); + // the key is the whole result key, not just the query path + private final Map dataFetcherResultType = new ConcurrentHashMap<>(); + public enum DataFetcherType { PROPERTY_DATA_FETCHER, CUSTOM } - public enum ResultType { + public enum DataFetcherResultType { COMPLETABLE_FUTURE_COMPLETED, COMPLETABLE_FUTURE_NOT_COMPLETED, MATERIALIZED @@ -50,6 +53,10 @@ void setDataFetcherType(String key, DataFetcherType dataFetcherType) { } } + void setDataFetcherResultType(String resultPath, DataFetcherResultType fetchedType) { + dataFetcherResultType.put(resultPath, fetchedType); + } + void incrementDataFetcherInvocationCount(String key) { dataFetcherInvocationCount.compute(key, (k, v) -> v == null ? 1 : v + 1); } @@ -122,6 +129,10 @@ public long getTotalExecutionTime() { return endTime - startTime; } + public Map getDataFetcherResultType() { + return dataFetcherResultType; + } + @Override public String toString() { return "ProfilerResult{" + @@ -134,6 +145,7 @@ public String toString() { ", totalPropertyDataFetcherInvocations=" + totalPropertyDataFetcherInvocations + ", dataFetcherInvocationCount=" + dataFetcherInvocationCount + ", dataFetcherTypeMap=" + dataFetcherTypeMap + + ", dataFetcherResultType=" + dataFetcherResultType + '}'; } } diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index 288847b371..adb6bfc575 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -7,6 +7,9 @@ import spock.lang.Specification import java.time.Duration import java.util.concurrent.CompletableFuture +import static graphql.ProfilerResult.DataFetcherResultType.COMPLETABLE_FUTURE_COMPLETED +import static graphql.ProfilerResult.DataFetcherResultType.COMPLETABLE_FUTURE_NOT_COMPLETED + class ProfilerTest extends Specification { @@ -35,7 +38,7 @@ class ProfilerTest extends Specification { result.getData() == [hello: "world"] then: - profilerResult.getFieldsFetched() == ["hello"] as Set + profilerResult.getFieldsFetched() == ["/hello"] as Set } @@ -71,7 +74,7 @@ class ProfilerTest extends Specification { result.getData() == [foo: [[id: "1", bar: "1"], [id: "2", bar: "2"], [id: "3", bar: "3"]]] then: - profilerResult.getFieldsFetched() == ["foo", "foo/bar", "foo/id"] as Set + profilerResult.getFieldsFetched() == ["/foo", "/foo/bar", "/foo/id"] as Set profilerResult.getTotalDataFetcherInvocations() == 7 profilerResult.getTotalCustomDataFetcherInvocations() == 4 profilerResult.getTotalPropertyDataFetcherInvocations() == 3 @@ -125,5 +128,47 @@ class ProfilerTest extends Specification { } + def "data fetcher result types"() { + given: + def sdl = ''' + type Query { + foo: Foo + } + type Foo { + id: String + name: String + } + ''' + def schema = TestUtil.schema(sdl, [ + Query: [ + foo: { DataFetchingEnvironment dfe -> + return CompletableFuture.supplyAsync { + Thread.sleep(100) + return [id: "1", name: "foo"] + } + } as DataFetcher], + Foo : [ + name: { DataFetchingEnvironment dfe -> + return CompletableFuture.completedFuture(dfe.source.name) + } as DataFetcher + ]]) + def graphql = GraphQL.newGraphQL(schema).build(); + + ExecutionInput ei = ExecutionInput.newExecutionInput() + .query("{ foo { id name } }") + .profileExecution(true) + .build() + + when: + def result = graphql.execute(ei) + def profilerResult = ei.getGraphQLContext().get(ProfilerResult.PROFILER_CONTEXT_KEY) as ProfilerResult + + then: + result.getData() == [foo: [id: "1", name: "foo"]] + profilerResult.getDataFetcherResultType() == ["/foo/name": COMPLETABLE_FUTURE_COMPLETED, "/foo": COMPLETABLE_FUTURE_NOT_COMPLETED] + + + } + } From b7379effccd5cc06af7fb542537e03a0194f068b Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Tue, 20 May 2025 21:07:43 +1000 Subject: [PATCH 05/25] operation details --- src/main/java/graphql/Profiler.java | 9 +++--- src/main/java/graphql/ProfilerImpl.java | 6 ++++ src/main/java/graphql/ProfilerResult.java | 26 +++++++++++++--- .../java/graphql/execution/Execution.java | 4 +-- src/test/groovy/graphql/ProfilerTest.groovy | 31 +++++++++++++++++++ 5 files changed, 66 insertions(+), 10 deletions(-) diff --git a/src/main/java/graphql/Profiler.java b/src/main/java/graphql/Profiler.java index 1732a76abf..233e95189c 100644 --- a/src/main/java/graphql/Profiler.java +++ b/src/main/java/graphql/Profiler.java @@ -3,6 +3,7 @@ import graphql.execution.EngineRunningObserver; import graphql.execution.ExecutionId; import graphql.execution.ResultPath; +import graphql.language.OperationDefinition; import graphql.schema.DataFetcher; import org.jspecify.annotations.NullMarked; import org.jspecify.annotations.Nullable; @@ -15,10 +16,6 @@ public interface Profiler { Profiler NO_OP = new Profiler() { }; - default void start() { - - } - default void rootFieldCount(int size) { @@ -39,4 +36,8 @@ default void fieldFetched(Object fetchedObject, DataFetcher dataFetcher, Resu default @Nullable EngineRunningObserver wrapEngineRunningObserver(EngineRunningObserver engineRunningObserver) { return engineRunningObserver; } + + default void operationDefinition(OperationDefinition operationDefinition) { + + } } diff --git a/src/main/java/graphql/ProfilerImpl.java b/src/main/java/graphql/ProfilerImpl.java index 7a51dc86fc..d047f5f760 100644 --- a/src/main/java/graphql/ProfilerImpl.java +++ b/src/main/java/graphql/ProfilerImpl.java @@ -3,6 +3,7 @@ import graphql.execution.EngineRunningObserver; import graphql.execution.ExecutionId; import graphql.execution.ResultPath; +import graphql.language.OperationDefinition; import graphql.schema.DataFetcher; import graphql.schema.PropertyDataFetcher; import graphql.schema.SingletonPropertyDataFetcher; @@ -91,4 +92,9 @@ private void runningStateChangedImpl(ExecutionId executionId, GraphQLContext gra Assert.assertShouldNeverHappen(); } } + + @Override + public void operationDefinition(OperationDefinition operationDefinition) { + profilerResult.setOperation(operationDefinition); + } } diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index 95e25f3371..a806b6b5ef 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -1,6 +1,7 @@ package graphql; import graphql.execution.ExecutionId; +import graphql.language.OperationDefinition; import java.util.LinkedHashSet; import java.util.Map; @@ -17,10 +18,9 @@ public class ProfilerResult { private long startTime; private long endTime; private long engineTotalRunningTime; - private final Set fieldsFetched = ConcurrentHashMap.newKeySet(); - private final AtomicInteger totalDataFetcherInvocations = new AtomicInteger(); private final AtomicInteger totalPropertyDataFetcherInvocations = new AtomicInteger(); + private final Set fieldsFetched = ConcurrentHashMap.newKeySet(); private final Map dataFetcherInvocationCount = new ConcurrentHashMap<>(); @@ -28,6 +28,8 @@ public class ProfilerResult { // the key is the whole result key, not just the query path private final Map dataFetcherResultType = new ConcurrentHashMap<>(); + private volatile String operationName; + private volatile String operationType; public enum DataFetcherType { @@ -75,6 +77,19 @@ void setTimes(long startTime, long endTime, long engineTotalRunningTime) { this.engineTotalRunningTime = engineTotalRunningTime; } + void setOperation(OperationDefinition operationDefinition) { + this.operationName = operationDefinition.getName(); + this.operationType = operationDefinition.getOperation().name(); + } + + + public String getOperationName() { + return operationName; + } + + public String getOperationType() { + return operationType; + } public Set getFieldsFetched() { return fieldsFetched; @@ -133,16 +148,19 @@ public Map getDataFetcherResultType() { return dataFetcherResultType; } + @Override public String toString() { return "ProfilerResult{" + "executionId=" + executionId + + ", operation=" + operationType + ":" + operationName + ", startTime=" + startTime + ", endTime=" + endTime + - ", engineTotalRunningTime=" + engineTotalRunningTime + - ", fieldsFetched=" + fieldsFetched + + ", totalRunTime=" + (endTime - startTime) + "(" + (endTime - startTime) / 1_000_000 + "ms)" + + ", engineTotalRunningTime=" + engineTotalRunningTime + "(" + engineTotalRunningTime / 1_000_000 + "ms)" + ", totalDataFetcherInvocations=" + totalDataFetcherInvocations + ", totalPropertyDataFetcherInvocations=" + totalPropertyDataFetcherInvocations + + ", fieldsFetched=" + fieldsFetched + ", dataFetcherInvocationCount=" + dataFetcherInvocationCount + ", dataFetcherTypeMap=" + dataFetcherTypeMap + ", dataFetcherResultType=" + dataFetcherResultType + diff --git a/src/main/java/graphql/execution/Execution.java b/src/main/java/graphql/execution/Execution.java index 25f78012f8..47b5958dc6 100644 --- a/src/main/java/graphql/execution/Execution.java +++ b/src/main/java/graphql/execution/Execution.java @@ -159,7 +159,7 @@ private CompletableFuture executeOperation(ExecutionContext exe OperationDefinition.Operation operation = operationDefinition.getOperation(); GraphQLObjectType operationRootType; - + executionContext.getProfiler().operationDefinition(operationDefinition); try { operationRootType = SchemaUtil.getOperationRootType(executionContext.getGraphQLSchema(), operationDefinition); } catch (RuntimeException rte) { @@ -292,7 +292,7 @@ private ExecutionResult mergeExtensionsBuilderIfPresent(ExecutionResult executio private boolean propagateErrorsOnNonNullContractFailure(List directives) { boolean jvmWideEnabled = Directives.isExperimentalDisableErrorPropagationDirectiveEnabled(); - if (! jvmWideEnabled) { + if (!jvmWideEnabled) { return true; } Directive foundDirective = NodeUtil.findNodeByName(directives, EXPERIMENTAL_DISABLE_ERROR_PROPAGATION_DIRECTIVE_DEFINITION.getName()); diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index adb6bfc575..abe2b21a01 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -170,5 +170,36 @@ class ProfilerTest extends Specification { } + def "operation details"() { + given: + def sdl = ''' + type Query { + hello: String + } + ''' + def schema = TestUtil.schema(sdl, [Query: [ + hello: { DataFetchingEnvironment dfe -> return "world" } as DataFetcher + ]]) + def graphql = GraphQL.newGraphQL(schema).build(); + + ExecutionInput ei = ExecutionInput.newExecutionInput() + .query("query MyQuery { hello }") + .profileExecution(true) + .build() + + when: + def result = graphql.execute(ei) + def profilerResult = ei.getGraphQLContext().get(ProfilerResult.PROFILER_CONTEXT_KEY) as ProfilerResult + + then: + result.getData() == [hello: "world"] + + then: + profilerResult.getOperationName() == "MyQuery" + profilerResult.getOperationType() == "QUERY" + + + } + } From 275eaac079cfc84c52bce072923e56850f8d0090 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Wed, 21 May 2025 11:26:45 +1000 Subject: [PATCH 06/25] wip --- src/main/java/graphql/GraphQL.java | 2 +- src/main/java/graphql/Profiler.java | 3 +- src/main/java/graphql/ProfilerImpl.java | 9 +++-- src/main/java/graphql/ProfilerResult.java | 39 +++++++++++++++++---- src/test/groovy/graphql/ProfilerTest.groovy | 6 ++-- 5 files changed, 44 insertions(+), 15 deletions(-) diff --git a/src/main/java/graphql/GraphQL.java b/src/main/java/graphql/GraphQL.java index 55121a1e6e..af692faf45 100644 --- a/src/main/java/graphql/GraphQL.java +++ b/src/main/java/graphql/GraphQL.java @@ -424,7 +424,7 @@ public CompletableFuture executeAsync(ExecutionInput executionI EngineRunningState engineRunningState = new EngineRunningState(executionInput, profiler); return engineRunningState.engineRun(() -> { ExecutionInput executionInputWithId = ensureInputHasId(executionInput); - profiler.setExecutionId(executionInputWithId.getExecutionId()); + profiler.executionInput(executionInputWithId); engineRunningState.updateExecutionId(executionInputWithId.getExecutionId()); CompletableFuture instrumentationStateCF = instrumentation.createStateAsync(new InstrumentationCreateStateParameters(this.graphQLSchema, executionInputWithId)); diff --git a/src/main/java/graphql/Profiler.java b/src/main/java/graphql/Profiler.java index 233e95189c..cd976f5790 100644 --- a/src/main/java/graphql/Profiler.java +++ b/src/main/java/graphql/Profiler.java @@ -1,7 +1,6 @@ package graphql; import graphql.execution.EngineRunningObserver; -import graphql.execution.ExecutionId; import graphql.execution.ResultPath; import graphql.language.OperationDefinition; import graphql.schema.DataFetcher; @@ -25,7 +24,7 @@ default void subSelectionCount(int size) { } - default void setExecutionId(ExecutionId executionId) { + default void executionInput(ExecutionInput executionInput) { } diff --git a/src/main/java/graphql/ProfilerImpl.java b/src/main/java/graphql/ProfilerImpl.java index d047f5f760..1a9170f6ad 100644 --- a/src/main/java/graphql/ProfilerImpl.java +++ b/src/main/java/graphql/ProfilerImpl.java @@ -3,6 +3,7 @@ import graphql.execution.EngineRunningObserver; import graphql.execution.ExecutionId; import graphql.execution.ResultPath; +import graphql.execution.instrumentation.dataloader.DataLoaderDispatchingContextKeys; import graphql.language.OperationDefinition; import graphql.schema.DataFetcher; import graphql.schema.PropertyDataFetcher; @@ -29,8 +30,10 @@ public ProfilerImpl(GraphQLContext graphQLContext) { } @Override - public void setExecutionId(ExecutionId executionId) { - profilerResult.setExecutionId(executionId); + public void executionInput(ExecutionInput executionInput) { + profilerResult.setExecutionId(executionInput.getExecutionId()); + boolean dataLoaderChainingEnabled = executionInput.getGraphQLContext().getBoolean(DataLoaderDispatchingContextKeys.ENABLE_DATA_LOADER_CHAINING, false); + profilerResult.setDataLoaderChainingEnabled(dataLoaderChainingEnabled); } @Override @@ -55,7 +58,7 @@ public void fieldFetched(Object fetchedObject, DataFetcher dataFetcher, Resul } else { dataFetcherResultType = ProfilerResult.DataFetcherResultType.MATERIALIZED; } - profilerResult.setDataFetcherResultType(path.toString(), dataFetcherResultType); + profilerResult.setDataFetcherResultType(key, dataFetcherResultType); } profilerResult.setDataFetcherType(key, dataFetcherType); diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index a806b6b5ef..3b67c91f23 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -26,10 +26,11 @@ public class ProfilerResult { private final Map dataFetcherInvocationCount = new ConcurrentHashMap<>(); private final Map dataFetcherTypeMap = new ConcurrentHashMap<>(); - // the key is the whole result key, not just the query path private final Map dataFetcherResultType = new ConcurrentHashMap<>(); private volatile String operationName; private volatile String operationType; + private volatile boolean dataLoaderChainingEnabled; + public enum DataFetcherType { @@ -47,6 +48,11 @@ public enum DataFetcherResultType { // setters are package private to prevent exposure + void setDataLoaderChainingEnabled(boolean dataLoaderChainingEnabled) { + this.dataLoaderChainingEnabled = dataLoaderChainingEnabled; + } + + void setDataFetcherType(String key, DataFetcherType dataFetcherType) { dataFetcherTypeMap.putIfAbsent(key, dataFetcherType); totalDataFetcherInvocations.incrementAndGet(); @@ -55,8 +61,8 @@ void setDataFetcherType(String key, DataFetcherType dataFetcherType) { } } - void setDataFetcherResultType(String resultPath, DataFetcherResultType fetchedType) { - dataFetcherResultType.put(resultPath, fetchedType); + void setDataFetcherResultType(String key, DataFetcherResultType fetchedType) { + dataFetcherResultType.putIfAbsent(key, fetchedType); } void incrementDataFetcherInvocationCount(String key) { @@ -148,9 +154,7 @@ public Map getDataFetcherResultType() { return dataFetcherResultType; } - - @Override - public String toString() { + public String fullSummary() { return "ProfilerResult{" + "executionId=" + executionId + ", operation=" + operationType + ":" + operationName + @@ -164,6 +168,29 @@ public String toString() { ", dataFetcherInvocationCount=" + dataFetcherInvocationCount + ", dataFetcherTypeMap=" + dataFetcherTypeMap + ", dataFetcherResultType=" + dataFetcherResultType + + ", dataLoaderChainingEnabled=" + dataLoaderChainingEnabled + '}'; } + + public String shortSummary() { + return "ProfilerResult{" + + "executionId=" + executionId + + ", operation=" + operationType + ":" + operationName + + ", startTime=" + startTime + + ", endTime=" + endTime + + ", totalRunTime=" + (endTime - startTime) + "(" + (endTime - startTime) / 1_000_000 + "ms)" + + ", engineTotalRunningTime=" + engineTotalRunningTime + "(" + engineTotalRunningTime / 1_000_000 + "ms)" + + ", totalDataFetcherInvocations=" + totalDataFetcherInvocations + + ", totalPropertyDataFetcherInvocations=" + totalPropertyDataFetcherInvocations + + ", fieldsFetchedCount=" + fieldsFetched.size() + + ", dataLoaderChainingEnabled=" + dataLoaderChainingEnabled + + '}'; + + + } + + @Override + public String toString() { + return shortSummary(); + } } diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index abe2b21a01..87d4f03c62 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -132,7 +132,7 @@ class ProfilerTest extends Specification { given: def sdl = ''' type Query { - foo: Foo + foo: [Foo] } type Foo { id: String @@ -144,7 +144,7 @@ class ProfilerTest extends Specification { foo: { DataFetchingEnvironment dfe -> return CompletableFuture.supplyAsync { Thread.sleep(100) - return [id: "1", name: "foo"] + return [[id: "1", name: "foo"]] } } as DataFetcher], Foo : [ @@ -164,7 +164,7 @@ class ProfilerTest extends Specification { def profilerResult = ei.getGraphQLContext().get(ProfilerResult.PROFILER_CONTEXT_KEY) as ProfilerResult then: - result.getData() == [foo: [id: "1", name: "foo"]] + result.getData() == [foo: [[id: "1", name: "foo"]]] profilerResult.getDataFetcherResultType() == ["/foo/name": COMPLETABLE_FUTURE_COMPLETED, "/foo": COMPLETABLE_FUTURE_NOT_COMPLETED] From cd002c0e9e5ce7a787db2c0ae4b3e3b3548abe04 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Wed, 21 May 2025 12:03:55 +1000 Subject: [PATCH 07/25] dataloader tracking --- src/main/java/graphql/Profiler.java | 13 ++++ src/main/java/graphql/ProfilerImpl.java | 15 ++++ src/main/java/graphql/ProfilerResult.java | 37 +++++++++- .../PerLevelDataLoaderDispatchStrategy.java | 6 +- .../schema/DataFetchingEnvironmentImpl.java | 21 +++++- .../graphql/schema/DataLoaderWithContext.java | 1 + src/test/groovy/graphql/ProfilerTest.groovy | 73 +++++++++++++++++++ 7 files changed, 161 insertions(+), 5 deletions(-) diff --git a/src/main/java/graphql/Profiler.java b/src/main/java/graphql/Profiler.java index cd976f5790..174d7211fc 100644 --- a/src/main/java/graphql/Profiler.java +++ b/src/main/java/graphql/Profiler.java @@ -26,6 +26,11 @@ default void subSelectionCount(int size) { default void executionInput(ExecutionInput executionInput) { + } + + default void dataLoaderUsed(String dataLoaderName) { + + } default void fieldFetched(Object fetchedObject, DataFetcher dataFetcher, ResultPath path) { @@ -39,4 +44,12 @@ default void fieldFetched(Object fetchedObject, DataFetcher dataFetcher, Resu default void operationDefinition(OperationDefinition operationDefinition) { } + + default void oldStrategyDispatchingAll(int level) { + + } + + default void chainedStrategyDispatching(int level) { + + } } diff --git a/src/main/java/graphql/ProfilerImpl.java b/src/main/java/graphql/ProfilerImpl.java index 1a9170f6ad..47654dc3ea 100644 --- a/src/main/java/graphql/ProfilerImpl.java +++ b/src/main/java/graphql/ProfilerImpl.java @@ -100,4 +100,19 @@ private void runningStateChangedImpl(ExecutionId executionId, GraphQLContext gra public void operationDefinition(OperationDefinition operationDefinition) { profilerResult.setOperation(operationDefinition); } + + @Override + public void dataLoaderUsed(String dataLoaderName) { + profilerResult.addDataLoaderUsed(dataLoaderName); + } + + @Override + public void chainedStrategyDispatching(int level) { + profilerResult.chainedStrategyDispatching(level); + } + + @Override + public void oldStrategyDispatchingAll(int level) { + profilerResult.oldStrategyDispatchingAll(level); + } } diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index 3b67c91f23..fd9df7f8fa 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -24,13 +24,15 @@ public class ProfilerResult { private final Map dataFetcherInvocationCount = new ConcurrentHashMap<>(); + private final Map dataLoaderLoadInvocations = new ConcurrentHashMap<>(); private final Map dataFetcherTypeMap = new ConcurrentHashMap<>(); private final Map dataFetcherResultType = new ConcurrentHashMap<>(); private volatile String operationName; private volatile String operationType; private volatile boolean dataLoaderChainingEnabled; - + private final Set oldStrategyDispatchingAll = ConcurrentHashMap.newKeySet(); + private final Set chainedStrategyDispatching = ConcurrentHashMap.newKeySet(); public enum DataFetcherType { @@ -88,6 +90,21 @@ void setOperation(OperationDefinition operationDefinition) { this.operationType = operationDefinition.getOperation().name(); } + void addDataLoaderUsed(String dataLoaderName) { + dataLoaderLoadInvocations.compute(dataLoaderName, (k, v) -> v == null ? 1 : v + 1); + } + + void oldStrategyDispatchingAll(int level) { + oldStrategyDispatchingAll.add(level); + } + + + void chainedStrategyDispatching(int level) { + chainedStrategyDispatching.add(level); + } + + + public String getOperationName() { return operationName; @@ -154,6 +171,18 @@ public Map getDataFetcherResultType() { return dataFetcherResultType; } + public Map getDataLoaderLoadInvocations() { + return dataLoaderLoadInvocations; + } + + public Set getChainedStrategyDispatching() { + return chainedStrategyDispatching; + } + + public Set getOldStrategyDispatchingAll() { + return oldStrategyDispatchingAll; + } + public String fullSummary() { return "ProfilerResult{" + "executionId=" + executionId + @@ -169,6 +198,9 @@ public String fullSummary() { ", dataFetcherTypeMap=" + dataFetcherTypeMap + ", dataFetcherResultType=" + dataFetcherResultType + ", dataLoaderChainingEnabled=" + dataLoaderChainingEnabled + + ", dataLoaderLoadInvocations=" + dataLoaderLoadInvocations + + ", oldStrategyDispatchingAll=" + oldStrategyDispatchingAll + + ", chainedStrategyDispatching" + chainedStrategyDispatching + '}'; } @@ -184,6 +216,9 @@ public String shortSummary() { ", totalPropertyDataFetcherInvocations=" + totalPropertyDataFetcherInvocations + ", fieldsFetchedCount=" + fieldsFetched.size() + ", dataLoaderChainingEnabled=" + dataLoaderChainingEnabled + + ", dataLoaderLoadInvocations=" + dataLoaderLoadInvocations + + ", oldStrategyDispatchingAll=" + oldStrategyDispatchingAll + + ", chainedStrategyDispatching" + chainedStrategyDispatching + '}'; diff --git a/src/main/java/graphql/execution/instrumentation/dataloader/PerLevelDataLoaderDispatchStrategy.java b/src/main/java/graphql/execution/instrumentation/dataloader/PerLevelDataLoaderDispatchStrategy.java index 30ccd838d4..c32b293950 100644 --- a/src/main/java/graphql/execution/instrumentation/dataloader/PerLevelDataLoaderDispatchStrategy.java +++ b/src/main/java/graphql/execution/instrumentation/dataloader/PerLevelDataLoaderDispatchStrategy.java @@ -3,6 +3,7 @@ import graphql.Assert; import graphql.GraphQLContext; import graphql.Internal; +import graphql.Profiler; import graphql.execution.DataLoaderDispatchStrategy; import graphql.execution.ExecutionContext; import graphql.execution.ExecutionStrategyParameters; @@ -43,6 +44,7 @@ public class PerLevelDataLoaderDispatchStrategy implements DataLoaderDispatchStr = new InterThreadMemoizedSupplier<>(() -> Executors.newScheduledThreadPool(Runtime.getRuntime().availableProcessors())); static final long DEFAULT_BATCH_WINDOW_NANO_SECONDS_DEFAULT = 500_000L; + private final Profiler profiler; private static class CallStack { @@ -187,6 +189,7 @@ public PerLevelDataLoaderDispatchStrategy(ExecutionContext executionContext) { }); this.enableDataLoaderChaining = graphQLContext.getBoolean(DataLoaderDispatchingContextKeys.ENABLE_DATA_LOADER_CHAINING, false); + this.profiler = executionContext.getProfiler(); } @Override @@ -395,13 +398,14 @@ private boolean checkLevelImpl(int level) { void dispatch(int level) { if (!enableDataLoaderChaining) { + profiler.oldStrategyDispatchingAll(level); DataLoaderRegistry dataLoaderRegistry = executionContext.getDataLoaderRegistry(); dataLoaderRegistry.dispatchAll(); return; } - Set resultPathWithDataLoaders = callStack.levelToResultPathWithDataLoader.get(level); if (resultPathWithDataLoaders != null) { + profiler.chainedStrategyDispatching(level); Set resultPathToDispatch = callStack.lock.callLocked(() -> { callStack.dispatchingStartedPerLevel.add(level); return resultPathWithDataLoaders diff --git a/src/main/java/graphql/schema/DataFetchingEnvironmentImpl.java b/src/main/java/graphql/schema/DataFetchingEnvironmentImpl.java index 0dd0e30674..da76a6efdf 100644 --- a/src/main/java/graphql/schema/DataFetchingEnvironmentImpl.java +++ b/src/main/java/graphql/schema/DataFetchingEnvironmentImpl.java @@ -4,6 +4,7 @@ import com.google.common.collect.ImmutableMap; import graphql.GraphQLContext; import graphql.Internal; +import graphql.Profiler; import graphql.collect.ImmutableKit; import graphql.collect.ImmutableMapWithNullValues; import graphql.execution.DataLoaderDispatchStrategy; @@ -78,7 +79,7 @@ private DataFetchingEnvironmentImpl(Builder builder) { this.queryDirectives = builder.queryDirectives; // internal state - this.dfeInternalState = new DFEInternalState(builder.dataLoaderDispatchStrategy); + this.dfeInternalState = new DFEInternalState(builder.dataLoaderDispatchStrategy, builder.profiler); } /** @@ -105,7 +106,8 @@ public static Builder newDataFetchingEnvironment(ExecutionContext executionConte .operationDefinition(executionContext.getOperationDefinition()) .variables(executionContext.getCoercedVariables().toMap()) .executionId(executionContext.getExecutionId()) - .dataLoaderDispatchStrategy(executionContext.getDataLoaderDispatcherStrategy()); + .dataLoaderDispatchStrategy(executionContext.getDataLoaderDispatcherStrategy()) + .profiler(executionContext.getProfiler()); } @@ -282,6 +284,7 @@ public static class Builder { private ImmutableMapWithNullValues variables; private QueryDirectives queryDirectives; private DataLoaderDispatchStrategy dataLoaderDispatchStrategy; + private Profiler profiler; public Builder(DataFetchingEnvironmentImpl env) { this.source = env.source; @@ -306,6 +309,7 @@ public Builder(DataFetchingEnvironmentImpl env) { this.variables = env.variables; this.queryDirectives = env.queryDirectives; this.dataLoaderDispatchStrategy = env.dfeInternalState.dataLoaderDispatchStrategy; + this.profiler = env.dfeInternalState.profiler; } public Builder() { @@ -433,18 +437,29 @@ public Builder dataLoaderDispatchStrategy(DataLoaderDispatchStrategy dataLoaderD this.dataLoaderDispatchStrategy = dataLoaderDispatcherStrategy; return this; } + + public Builder profiler(Profiler profiler) { + this.profiler = profiler; + return this; + } } @Internal public static class DFEInternalState { final DataLoaderDispatchStrategy dataLoaderDispatchStrategy; + final Profiler profiler; - public DFEInternalState(DataLoaderDispatchStrategy dataLoaderDispatchStrategy) { + public DFEInternalState(DataLoaderDispatchStrategy dataLoaderDispatchStrategy, Profiler profiler) { this.dataLoaderDispatchStrategy = dataLoaderDispatchStrategy; + this.profiler = profiler; } public DataLoaderDispatchStrategy getDataLoaderDispatchStrategy() { return dataLoaderDispatchStrategy; } + + public Profiler getProfiler() { + return profiler; + } } } diff --git a/src/main/java/graphql/schema/DataLoaderWithContext.java b/src/main/java/graphql/schema/DataLoaderWithContext.java index a4b56814ca..cacf1591a4 100644 --- a/src/main/java/graphql/schema/DataLoaderWithContext.java +++ b/src/main/java/graphql/schema/DataLoaderWithContext.java @@ -31,6 +31,7 @@ public CompletableFuture load(@NonNull K key, @Nullable Object keyContext) { int level = dfe.getExecutionStepInfo().getPath().getLevel(); String path = dfe.getExecutionStepInfo().getPath().toString(); DataFetchingEnvironmentImpl.DFEInternalState dfeInternalState = (DataFetchingEnvironmentImpl.DFEInternalState) dfeImpl.toInternal(); + dfeInternalState.getProfiler().dataLoaderUsed(dataLoaderName); if (dfeInternalState.getDataLoaderDispatchStrategy() instanceof PerLevelDataLoaderDispatchStrategy) { ((PerLevelDataLoaderDispatchStrategy) dfeInternalState.dataLoaderDispatchStrategy).newDataLoaderLoadCall(path, level, delegate, dataLoaderName, key); } diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index 87d4f03c62..5b42d86566 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -1,14 +1,23 @@ package graphql + import graphql.schema.DataFetcher import graphql.schema.DataFetchingEnvironment +import org.awaitility.Awaitility +import org.dataloader.BatchLoader +import org.dataloader.DataLoader +import org.dataloader.DataLoaderFactory +import org.dataloader.DataLoaderRegistry import spock.lang.Specification import java.time.Duration import java.util.concurrent.CompletableFuture +import static graphql.ExecutionInput.newExecutionInput import static graphql.ProfilerResult.DataFetcherResultType.COMPLETABLE_FUTURE_COMPLETED import static graphql.ProfilerResult.DataFetcherResultType.COMPLETABLE_FUTURE_NOT_COMPLETED +import static graphql.execution.instrumentation.dataloader.DataLoaderDispatchingContextKeys.setEnableDataLoaderChaining +import static java.util.concurrent.CompletableFuture.supplyAsync class ProfilerTest extends Specification { @@ -201,5 +210,69 @@ class ProfilerTest extends Specification { } + def "dataloader usage"() { + given: + def sdl = ''' + + type Query { + dogName: String + catName: String + } + ''' + int batchLoadCalls = 0 + BatchLoader batchLoader = { keys -> + return supplyAsync { + batchLoadCalls++ + Thread.sleep(250) + println "BatchLoader called with keys: $keys" + assert keys.size() == 2 + return ["Luna", "Tiger"] + } + } + + DataLoader nameDataLoader = DataLoaderFactory.newDataLoader(batchLoader); + + DataLoaderRegistry dataLoaderRegistry = new DataLoaderRegistry(); + dataLoaderRegistry.register("name", nameDataLoader); + + def df1 = { env -> + return env.getDataLoader("name").load("Key1").thenCompose { + result -> + { + return env.getDataLoader("name").load(result) + } + } + } as DataFetcher + + def df2 = { env -> + return env.getDataLoader("name").load("Key2").thenCompose { + result -> + { + return env.getDataLoader("name").load(result) + } + } + } as DataFetcher + + def fetchers = ["Query": ["dogName": df1, "catName": df2]] + def schema = TestUtil.schema(sdl, fetchers) + def graphQL = GraphQL.newGraphQL(schema).build() + + def query = "{ dogName catName } " + def ei = newExecutionInput(query).dataLoaderRegistry(dataLoaderRegistry).profileExecution(true).build() + setEnableDataLoaderChaining(ei.graphQLContext, true) + + when: + def efCF = graphQL.executeAsync(ei) + Awaitility.await().until { efCF.isDone() } + def er = efCF.get() + def profilerResult = ei.getGraphQLContext().get(ProfilerResult.PROFILER_CONTEXT_KEY) as ProfilerResult + then: + er.data == [dogName: "Luna", catName: "Tiger"] + batchLoadCalls == 2 + profilerResult.getDataLoaderLoadInvocations() == [name: 4] + profilerResult.getChainedStrategyDispatching() == [1] as Set + + } + } From 450a9fc48ffadd260239910f6198a7a4cd9a5042 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Mon, 26 May 2025 14:47:50 +1000 Subject: [PATCH 08/25] track dataloader dispatch --- src/main/java/graphql/Profiler.java | 16 +++-- src/main/java/graphql/ProfilerImpl.java | 11 ++++ src/main/java/graphql/ProfilerResult.java | 64 ++++++++++++++++++- .../PerLevelDataLoaderDispatchStrategy.java | 22 ++++++- src/test/groovy/graphql/ProfilerTest.groovy | 8 +++ .../DataLoaderDispatcherTest.groovy | 17 ++--- 6 files changed, 116 insertions(+), 22 deletions(-) diff --git a/src/main/java/graphql/Profiler.java b/src/main/java/graphql/Profiler.java index 174d7211fc..7d6f94346f 100644 --- a/src/main/java/graphql/Profiler.java +++ b/src/main/java/graphql/Profiler.java @@ -16,13 +16,6 @@ public interface Profiler { }; - default void rootFieldCount(int size) { - - } - - default void subSelectionCount(int size) { - - } default void executionInput(ExecutionInput executionInput) { @@ -52,4 +45,13 @@ default void oldStrategyDispatchingAll(int level) { default void chainedStrategyDispatching(int level) { } + + default void batchLoadedOldStrategy(String name, int level, int count) { + + + } + + default void batchLoadedNewStrategy(String name, @Nullable Integer level, int count) { + + } } diff --git a/src/main/java/graphql/ProfilerImpl.java b/src/main/java/graphql/ProfilerImpl.java index 47654dc3ea..be6e82f368 100644 --- a/src/main/java/graphql/ProfilerImpl.java +++ b/src/main/java/graphql/ProfilerImpl.java @@ -9,6 +9,7 @@ import graphql.schema.PropertyDataFetcher; import graphql.schema.SingletonPropertyDataFetcher; import org.jspecify.annotations.NullMarked; +import org.jspecify.annotations.Nullable; import java.util.concurrent.CompletableFuture; import java.util.concurrent.atomic.AtomicLong; @@ -115,4 +116,14 @@ public void chainedStrategyDispatching(int level) { public void oldStrategyDispatchingAll(int level) { profilerResult.oldStrategyDispatchingAll(level); } + + @Override + public void batchLoadedOldStrategy(String name, int level, int count) { + profilerResult.addDispatchEvent(name, level, count, false); + } + + @Override + public void batchLoadedNewStrategy(String name, @Nullable Integer level, int count) { + profilerResult.addDispatchEvent(name, level, count, true); + } } diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index fd9df7f8fa..4138e0eb8b 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -2,14 +2,20 @@ import graphql.execution.ExecutionId; import graphql.language.OperationDefinition; +import org.jspecify.annotations.NullMarked; +import org.jspecify.annotations.Nullable; +import java.util.ArrayList; +import java.util.Collections; import java.util.LinkedHashSet; +import java.util.List; import java.util.Map; import java.util.Set; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.atomic.AtomicInteger; @ExperimentalApi +@NullMarked public class ProfilerResult { public static final String PROFILER_CONTEXT_KEY = "__GJ_PROFILER"; @@ -34,6 +40,49 @@ public class ProfilerResult { private final Set oldStrategyDispatchingAll = ConcurrentHashMap.newKeySet(); private final Set chainedStrategyDispatching = ConcurrentHashMap.newKeySet(); + private final List dispatchEvents = Collections.synchronizedList(new ArrayList<>()); + + + public static class DispatchEvent { + final String dataLoaderName; + final @Nullable + Integer level; // can be null for delayed dispatching + final int count; + private final boolean dataLoaderChainingEnabled; + + public DispatchEvent(String dataLoaderName, @Nullable Integer level, int count, boolean dataLoaderChainingEnabled) { + this.dataLoaderName = dataLoaderName; + this.level = level; + this.count = count; + this.dataLoaderChainingEnabled = dataLoaderChainingEnabled; + } + + public String getDataLoaderName() { + return dataLoaderName; + } + + public @Nullable Integer getLevel() { + return level; + } + + public int getCount() { + return count; + } + + public boolean isDataLoaderChainingEnabled() { + return dataLoaderChainingEnabled; + } + + @Override + public String toString() { + return "DispatchEvent{" + + "dataLoaderName='" + dataLoaderName + '\'' + + ", level=" + level + + ", count=" + count + + ", dataLoaderChainingEnabled=" + dataLoaderChainingEnabled + + '}'; + } + } public enum DataFetcherType { PROPERTY_DATA_FETCHER, @@ -103,8 +152,11 @@ void chainedStrategyDispatching(int level) { chainedStrategyDispatching.add(level); } + void addDispatchEvent(String dataLoaderName, @Nullable Integer level, int count, boolean dataLoaderChainingEnabled) { + dispatchEvents.add(new DispatchEvent(dataLoaderName, level, count, dataLoaderChainingEnabled)); + } - + // public getters public String getOperationName() { return operationName; @@ -183,6 +235,14 @@ public Set getOldStrategyDispatchingAll() { return oldStrategyDispatchingAll; } + public boolean isDataLoaderChainingEnabled() { + return dataLoaderChainingEnabled; + } + + public List getDispatchEvents() { + return dispatchEvents; + } + public String fullSummary() { return "ProfilerResult{" + "executionId=" + executionId + @@ -201,6 +261,7 @@ public String fullSummary() { ", dataLoaderLoadInvocations=" + dataLoaderLoadInvocations + ", oldStrategyDispatchingAll=" + oldStrategyDispatchingAll + ", chainedStrategyDispatching" + chainedStrategyDispatching + + ", dispatchEvents" + dispatchEvents + '}'; } @@ -219,6 +280,7 @@ public String shortSummary() { ", dataLoaderLoadInvocations=" + dataLoaderLoadInvocations + ", oldStrategyDispatchingAll=" + oldStrategyDispatchingAll + ", chainedStrategyDispatching" + chainedStrategyDispatching + + ", dispatchEvents" + dispatchEvents + '}'; diff --git a/src/main/java/graphql/execution/instrumentation/dataloader/PerLevelDataLoaderDispatchStrategy.java b/src/main/java/graphql/execution/instrumentation/dataloader/PerLevelDataLoaderDispatchStrategy.java index ca51f38a53..f35ea1e5fa 100644 --- a/src/main/java/graphql/execution/instrumentation/dataloader/PerLevelDataLoaderDispatchStrategy.java +++ b/src/main/java/graphql/execution/instrumentation/dataloader/PerLevelDataLoaderDispatchStrategy.java @@ -480,7 +480,7 @@ void dispatch(int level, CallStack callStack) { if (!enableDataLoaderChaining) { profiler.oldStrategyDispatchingAll(level); DataLoaderRegistry dataLoaderRegistry = executionContext.getDataLoaderRegistry(); - dataLoaderRegistry.dispatchAll(); + dispatchAll(dataLoaderRegistry, level); return; } Set resultPathWithDataLoaders = callStack.levelToResultPathWithDataLoader.get(level); @@ -502,8 +502,18 @@ void dispatch(int level, CallStack callStack) { } } + private void dispatchAll(DataLoaderRegistry dataLoaderRegistry, int level) { + for (DataLoader dataLoader : dataLoaderRegistry.getDataLoaders()) { + dataLoader.dispatch().whenComplete((objects, throwable) -> { + if (objects != null && objects.size() > 0) { + profiler.batchLoadedOldStrategy(dataLoader.getName(), level, objects.size()); + } + }); + } + } - public void dispatchDLCFImpl(Set resultPathsToDispatch, Integer level, CallStack callStack) { + + public void dispatchDLCFImpl(Set resultPathsToDispatch, @Nullable Integer level, CallStack callStack) { // filter out all DataLoaderCFS that are matching the fields we want to dispatch List relevantResultPathWithDataLoader = new ArrayList<>(); @@ -524,7 +534,13 @@ public void dispatchDLCFImpl(Set resultPathsToDispatch, Integer level, C } List allDispatchedCFs = new ArrayList<>(); for (ResultPathWithDataLoader resultPathWithDataLoader : relevantResultPathWithDataLoader) { - allDispatchedCFs.add(resultPathWithDataLoader.dataLoader.dispatch()); + CompletableFuture dispatch = resultPathWithDataLoader.dataLoader.dispatch(); + allDispatchedCFs.add(dispatch); + dispatch.whenComplete((objects, throwable) -> { + if (objects != null && objects.size() > 0) { + profiler.batchLoadedNewStrategy(resultPathWithDataLoader.name, level, objects.size()); + } + }); } CompletableFuture.allOf(allDispatchedCFs.toArray(new CompletableFuture[0])) .whenComplete((unused, throwable) -> { diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index 5b42d86566..b606763748 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -269,8 +269,16 @@ class ProfilerTest extends Specification { then: er.data == [dogName: "Luna", catName: "Tiger"] batchLoadCalls == 2 + profilerResult.isDataLoaderChainingEnabled() profilerResult.getDataLoaderLoadInvocations() == [name: 4] profilerResult.getChainedStrategyDispatching() == [1] as Set + profilerResult.getDispatchEvents().size() == 2 + profilerResult.getDispatchEvents()[0].dataLoaderName == "name" + profilerResult.getDispatchEvents()[0].level == 1 + profilerResult.getDispatchEvents()[0].count == 2 + profilerResult.getDispatchEvents()[1].dataLoaderName == "name" + profilerResult.getDispatchEvents()[1].level == 1 + profilerResult.getDispatchEvents()[1].count == 2 } diff --git a/src/test/groovy/graphql/execution/instrumentation/dataloader/DataLoaderDispatcherTest.groovy b/src/test/groovy/graphql/execution/instrumentation/dataloader/DataLoaderDispatcherTest.groovy index 27e820750f..2aaad6090a 100644 --- a/src/test/groovy/graphql/execution/instrumentation/dataloader/DataLoaderDispatcherTest.groovy +++ b/src/test/groovy/graphql/execution/instrumentation/dataloader/DataLoaderDispatcherTest.groovy @@ -56,15 +56,9 @@ class DataLoaderDispatcherTest extends Specification { ] - def "dispatch is called if there are data loaders"() { + def "basic dataloader dispatch test"() { def dispatchedCalled = false - def dataLoaderRegistry = new DataLoaderRegistry() { - @Override - void dispatchAll() { - dispatchedCalled = true - super.dispatchAll() - } - } + def dataLoaderRegistry = new DataLoaderRegistry() def dataLoader = DataLoaderFactory.newDataLoader(new BatchLoader() { @Override CompletionStage load(List keys) { @@ -78,10 +72,11 @@ class DataLoaderDispatcherTest extends Specification { executionInput.getGraphQLContext().put(DataLoaderDispatchingContextKeys.ENABLE_DATA_LOADER_CHAINING, false) when: - def er = graphQL.execute(executionInput) + def er = graphQL.executeAsync(executionInput) + Awaitility.await().until { er.isDone() } then: - er.errors.isEmpty() - dispatchedCalled + er.get().data == [hero: [name: 'R2-D2']] + } def "enhanced execution input is respected"() { From 5e9e7133eb2afa041adfa830e739c820c7d0aa70 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Wed, 28 May 2025 09:37:42 +1000 Subject: [PATCH 09/25] track dataloader dispatch --- src/main/java/graphql/ProfilerImpl.java | 4 +- src/main/java/graphql/ProfilerResult.java | 42 ++++++++++++------- .../dataloader/DeferWithDataLoaderTest.groovy | 2 + 3 files changed, 32 insertions(+), 16 deletions(-) diff --git a/src/main/java/graphql/ProfilerImpl.java b/src/main/java/graphql/ProfilerImpl.java index be6e82f368..97b2d17cb4 100644 --- a/src/main/java/graphql/ProfilerImpl.java +++ b/src/main/java/graphql/ProfilerImpl.java @@ -119,11 +119,11 @@ public void oldStrategyDispatchingAll(int level) { @Override public void batchLoadedOldStrategy(String name, int level, int count) { - profilerResult.addDispatchEvent(name, level, count, false); + profilerResult.addDispatchEvent(name, level, count); } @Override public void batchLoadedNewStrategy(String name, @Nullable Integer level, int count) { - profilerResult.addDispatchEvent(name, level, count, true); + profilerResult.addDispatchEvent(name, level, count); } } diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index 4138e0eb8b..0789ad2670 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -48,13 +48,11 @@ public static class DispatchEvent { final @Nullable Integer level; // can be null for delayed dispatching final int count; - private final boolean dataLoaderChainingEnabled; - public DispatchEvent(String dataLoaderName, @Nullable Integer level, int count, boolean dataLoaderChainingEnabled) { + public DispatchEvent(String dataLoaderName, @Nullable Integer level, int count) { this.dataLoaderName = dataLoaderName; this.level = level; this.count = count; - this.dataLoaderChainingEnabled = dataLoaderChainingEnabled; } public String getDataLoaderName() { @@ -69,17 +67,12 @@ public int getCount() { return count; } - public boolean isDataLoaderChainingEnabled() { - return dataLoaderChainingEnabled; - } - @Override public String toString() { return "DispatchEvent{" + "dataLoaderName='" + dataLoaderName + '\'' + ", level=" + level + ", count=" + count + - ", dataLoaderChainingEnabled=" + dataLoaderChainingEnabled + '}'; } } @@ -152,8 +145,8 @@ void chainedStrategyDispatching(int level) { chainedStrategyDispatching.add(level); } - void addDispatchEvent(String dataLoaderName, @Nullable Integer level, int count, boolean dataLoaderChainingEnabled) { - dispatchEvents.add(new DispatchEvent(dataLoaderName, level, count, dataLoaderChainingEnabled)); + void addDispatchEvent(String dataLoaderName, @Nullable Integer level, int count) { + dispatchEvents.add(new DispatchEvent(dataLoaderName, level, count)); } // public getters @@ -260,8 +253,8 @@ public String fullSummary() { ", dataLoaderChainingEnabled=" + dataLoaderChainingEnabled + ", dataLoaderLoadInvocations=" + dataLoaderLoadInvocations + ", oldStrategyDispatchingAll=" + oldStrategyDispatchingAll + - ", chainedStrategyDispatching" + chainedStrategyDispatching + - ", dispatchEvents" + dispatchEvents + + ", chainedStrategyDispatching=" + chainedStrategyDispatching + + ", dispatchEvents=" + printDispatchEvents() + '}'; } @@ -279,13 +272,34 @@ public String shortSummary() { ", dataLoaderChainingEnabled=" + dataLoaderChainingEnabled + ", dataLoaderLoadInvocations=" + dataLoaderLoadInvocations + ", oldStrategyDispatchingAll=" + oldStrategyDispatchingAll + - ", chainedStrategyDispatching" + chainedStrategyDispatching + - ", dispatchEvents" + dispatchEvents + + ", chainedStrategyDispatching=" + chainedStrategyDispatching + + ", dispatchEvents=" + printDispatchEvents() + '}'; } + private String printDispatchEvents() { + if (dispatchEvents.isEmpty()) { + return "[]"; + } + StringBuilder sb = new StringBuilder(); + sb.append("["); + int i = 0; + for (DispatchEvent event : dispatchEvents) { + sb.append("dataLoader=") + .append(event.getDataLoaderName()) + .append(", level=") + .append(event.getLevel()) + .append(", count=").append(event.getCount()); + if (i++ < dispatchEvents.size() - 1) { + sb.append("; "); + } + } + sb.append("]"); + return sb.toString(); + } + @Override public String toString() { return shortSummary(); diff --git a/src/test/groovy/graphql/execution/instrumentation/dataloader/DeferWithDataLoaderTest.groovy b/src/test/groovy/graphql/execution/instrumentation/dataloader/DeferWithDataLoaderTest.groovy index 5427f7e504..2978d31c91 100644 --- a/src/test/groovy/graphql/execution/instrumentation/dataloader/DeferWithDataLoaderTest.groovy +++ b/src/test/groovy/graphql/execution/instrumentation/dataloader/DeferWithDataLoaderTest.groovy @@ -11,6 +11,7 @@ import org.awaitility.Awaitility import org.dataloader.BatchLoader import org.dataloader.DataLoaderFactory import org.dataloader.DataLoaderRegistry +import spock.lang.RepeatUntilFailure import spock.lang.Specification import java.time.Duration @@ -348,6 +349,7 @@ class DeferWithDataLoaderTest extends Specification { batchCompareDataFetchers.productsForDepartmentsBatchLoaderCounter.get() == 1 } + @RepeatUntilFailure(maxAttempts = 50) def "dataloader in initial result and chained dataloader inside nested defer block"() { given: def sdl = ''' From 221b4161ba97e55bed36eaa8d19d46fb46fa8034 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Tue, 1 Jul 2025 10:30:26 +1000 Subject: [PATCH 10/25] non nullable handling --- src/main/java/graphql/EngineRunningState.java | 3 +++ src/main/java/graphql/ProfilerResult.java | 5 +++++ .../dataloader/PerLevelDataLoaderDispatchStrategy.java | 1 + .../java/graphql/schema/DataFetchingEnvironmentImpl.java | 2 +- 4 files changed, 10 insertions(+), 1 deletion(-) diff --git a/src/main/java/graphql/EngineRunningState.java b/src/main/java/graphql/EngineRunningState.java index 9b901f2367..1dbeb44f55 100644 --- a/src/main/java/graphql/EngineRunningState.java +++ b/src/main/java/graphql/EngineRunningState.java @@ -182,6 +182,9 @@ public void updateExecutionId(ExecutionId executionId) { } private void changeOfState(EngineRunningObserver.RunningState runningState) { + Assert.assertNotNull(engineRunningObserver); + Assert.assertNotNull(executionId); + Assert.assertNotNull(graphQLContext); engineRunningObserver.runningStateChanged(executionId, graphQLContext, runningState); } diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index 0789ad2670..9dba350a73 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -20,6 +20,7 @@ public class ProfilerResult { public static final String PROFILER_CONTEXT_KEY = "__GJ_PROFILER"; + @Nullable private volatile ExecutionId executionId; private long startTime; private long endTime; @@ -34,7 +35,9 @@ public class ProfilerResult { private final Map dataFetcherTypeMap = new ConcurrentHashMap<>(); private final Map dataFetcherResultType = new ConcurrentHashMap<>(); + @Nullable private volatile String operationName; + @Nullable private volatile String operationType; private volatile boolean dataLoaderChainingEnabled; private final Set oldStrategyDispatchingAll = ConcurrentHashMap.newKeySet(); @@ -152,10 +155,12 @@ void addDispatchEvent(String dataLoaderName, @Nullable Integer level, int count) // public getters public String getOperationName() { + Assert.assertNotNull(operationName); return operationName; } public String getOperationType() { + Assert.assertNotNull(operationType); return operationType; } diff --git a/src/main/java/graphql/execution/instrumentation/dataloader/PerLevelDataLoaderDispatchStrategy.java b/src/main/java/graphql/execution/instrumentation/dataloader/PerLevelDataLoaderDispatchStrategy.java index 0ceca68a99..83f6ac9e7c 100644 --- a/src/main/java/graphql/execution/instrumentation/dataloader/PerLevelDataLoaderDispatchStrategy.java +++ b/src/main/java/graphql/execution/instrumentation/dataloader/PerLevelDataLoaderDispatchStrategy.java @@ -516,6 +516,7 @@ private void dispatchAll(DataLoaderRegistry dataLoaderRegistry, int level) { for (DataLoader dataLoader : dataLoaderRegistry.getDataLoaders()) { dataLoader.dispatch().whenComplete((objects, throwable) -> { if (objects != null && objects.size() > 0) { + Assert.assertNotNull(dataLoader.getName()); profiler.batchLoadedOldStrategy(dataLoader.getName(), level, objects.size()); } }); diff --git a/src/main/java/graphql/schema/DataFetchingEnvironmentImpl.java b/src/main/java/graphql/schema/DataFetchingEnvironmentImpl.java index 9ddeccfbbb..6d34f9206c 100644 --- a/src/main/java/graphql/schema/DataFetchingEnvironmentImpl.java +++ b/src/main/java/graphql/schema/DataFetchingEnvironmentImpl.java @@ -471,7 +471,7 @@ public static class DFEInternalState { final Profiler profiler; final AlternativeCallContext alternativeCallContext; - public DFEInternalState(DataLoaderDispatchStrategy dataLoaderDispatchStrategy, AlternativeCallContext deferredCallContext, Profiler profiler) { + public DFEInternalState(DataLoaderDispatchStrategy dataLoaderDispatchStrategy, AlternativeCallContext alternativeCallContext, Profiler profiler) { this.dataLoaderDispatchStrategy = dataLoaderDispatchStrategy; this.alternativeCallContext = alternativeCallContext; this.profiler = profiler; From 4008c1168e036ea8202fd8c97241133116a98c0e Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Wed, 9 Jul 2025 10:16:51 +1000 Subject: [PATCH 11/25] master merging --- src/main/java/graphql/EngineRunningState.java | 26 +++---------------- src/main/java/graphql/Profiler.java | 2 +- src/main/java/graphql/ProfilerImpl.java | 2 +- .../graphql/execution/ExecutionContext.java | 1 - .../AsyncExecutionStrategyTest.groovy | 10 +++---- .../AsyncSerialExecutionStrategyTest.groovy | 4 +-- .../execution/ExecutionStrategyTest.groovy | 2 +- .../FieldValidationTest.groovy | 3 +-- 8 files changed, 15 insertions(+), 35 deletions(-) diff --git a/src/main/java/graphql/EngineRunningState.java b/src/main/java/graphql/EngineRunningState.java index 114a5f2c3c..d73b1003a4 100644 --- a/src/main/java/graphql/EngineRunningState.java +++ b/src/main/java/graphql/EngineRunningState.java @@ -36,32 +36,14 @@ public class EngineRunningState { private final AtomicInteger isRunning = new AtomicInteger(0); - @VisibleForTesting - public EngineRunningState() { - this.engineRunningObserver = null; - this.graphQLContext = null; - this.executionId = null; - } - - public EngineRunningState(ExecutionInput executionInput) { - this.executionInput = executionInput; - this.graphQLContext = executionInput.getGraphQLContext(); - this.executionId = executionInput.getExecutionId(); - this.engineRunningObserver = executionInput.getGraphQLContext().get(EngineRunningObserver.ENGINE_RUNNING_OBSERVER_KEY); - } public EngineRunningState(ExecutionInput executionInput, Profiler profiler) { EngineRunningObserver engineRunningObserver = executionInput.getGraphQLContext().get(EngineRunningObserver.ENGINE_RUNNING_OBSERVER_KEY); EngineRunningObserver wrappedObserver = profiler.wrapEngineRunningObserver(engineRunningObserver); - if (wrappedObserver != null) { - this.engineRunningObserver = wrappedObserver; - this.graphQLContext = executionInput.getGraphQLContext(); - this.executionId = executionInput.getExecutionId(); - } else { - this.engineRunningObserver = null; - this.graphQLContext = null; - this.executionId = null; - } + this.engineRunningObserver = wrappedObserver; + this.executionInput = executionInput; + this.graphQLContext = executionInput.getGraphQLContext(); + this.executionId = executionInput.getExecutionId(); } diff --git a/src/main/java/graphql/Profiler.java b/src/main/java/graphql/Profiler.java index 7d6f94346f..28b1f966fe 100644 --- a/src/main/java/graphql/Profiler.java +++ b/src/main/java/graphql/Profiler.java @@ -30,7 +30,7 @@ default void fieldFetched(Object fetchedObject, DataFetcher dataFetcher, Resu } - default @Nullable EngineRunningObserver wrapEngineRunningObserver(EngineRunningObserver engineRunningObserver) { + default @Nullable EngineRunningObserver wrapEngineRunningObserver(@Nullable EngineRunningObserver engineRunningObserver) { return engineRunningObserver; } diff --git a/src/main/java/graphql/ProfilerImpl.java b/src/main/java/graphql/ProfilerImpl.java index 97b2d17cb4..de60b1fb94 100644 --- a/src/main/java/graphql/ProfilerImpl.java +++ b/src/main/java/graphql/ProfilerImpl.java @@ -66,7 +66,7 @@ public void fieldFetched(Object fetchedObject, DataFetcher dataFetcher, Resul } @Override - public EngineRunningObserver wrapEngineRunningObserver(EngineRunningObserver engineRunningObserver) { + public EngineRunningObserver wrapEngineRunningObserver(@Nullable EngineRunningObserver engineRunningObserver) { // nothing to wrap here return new EngineRunningObserver() { @Override diff --git a/src/main/java/graphql/execution/ExecutionContext.java b/src/main/java/graphql/execution/ExecutionContext.java index b8ac941d91..c6a7edc916 100644 --- a/src/main/java/graphql/execution/ExecutionContext.java +++ b/src/main/java/graphql/execution/ExecutionContext.java @@ -391,7 +391,6 @@ Throwable possibleCancellation(@Nullable Throwable currentThrowable) { public Profiler getProfiler() { return profiler; } -} @Internal void throwIfCancelled() throws AbortExecutionException { diff --git a/src/test/groovy/graphql/execution/AsyncExecutionStrategyTest.groovy b/src/test/groovy/graphql/execution/AsyncExecutionStrategyTest.groovy index f9585f59c1..0c66a30e18 100644 --- a/src/test/groovy/graphql/execution/AsyncExecutionStrategyTest.groovy +++ b/src/test/groovy/graphql/execution/AsyncExecutionStrategyTest.groovy @@ -114,7 +114,7 @@ abstract class AsyncExecutionStrategyTest extends Specification { .executionInput(ei) .locale(Locale.getDefault()) .profiler(Profiler.NO_OP) - .engineRunningState(new EngineRunningState(ei)) + .engineRunningState(new EngineRunningState(ei, Profiler.NO_OP)) .build() ExecutionStrategyParameters executionStrategyParameters = ExecutionStrategyParameters .newParameters() @@ -159,7 +159,7 @@ abstract class AsyncExecutionStrategyTest extends Specification { .locale(Locale.getDefault()) .graphQLContext(graphqlContextMock) .executionInput(ei) - .engineRunningState(new EngineRunningState(ei)) + .engineRunningState(new EngineRunningState(ei, Profiler.NO_OP)) .profiler(Profiler.NO_OP) .build() ExecutionStrategyParameters executionStrategyParameters = ExecutionStrategyParameters @@ -206,7 +206,7 @@ abstract class AsyncExecutionStrategyTest extends Specification { .instrumentation(SimplePerformantInstrumentation.INSTANCE) .graphQLContext(graphqlContextMock) .executionInput(ei) - .engineRunningState(new EngineRunningState(ei)) + .engineRunningState(new EngineRunningState(ei, Profiler.NO_OP)) .locale(Locale.getDefault()) .profiler(Profiler.NO_OP) .build() @@ -254,7 +254,7 @@ abstract class AsyncExecutionStrategyTest extends Specification { .locale(Locale.getDefault()) .graphQLContext(graphqlContextMock) .executionInput(ei) - .engineRunningState(new EngineRunningState(ei)) + .engineRunningState(new EngineRunningState(ei, Profiler.NO_OP)) .profiler(Profiler.NO_OP) .build() ExecutionStrategyParameters executionStrategyParameters = ExecutionStrategyParameters @@ -299,7 +299,7 @@ abstract class AsyncExecutionStrategyTest extends Specification { .graphQLContext(graphqlContextMock) .executionInput(ei) .locale(Locale.getDefault()) - .engineRunningState(new EngineRunningState(ei)) + .engineRunningState(new EngineRunningState(ei, Profiler.NO_OP)) .profiler(Profiler.NO_OP) .instrumentation(new SimplePerformantInstrumentation() { diff --git a/src/test/groovy/graphql/execution/AsyncSerialExecutionStrategyTest.groovy b/src/test/groovy/graphql/execution/AsyncSerialExecutionStrategyTest.groovy index 74ae8e3c00..6089e75a88 100644 --- a/src/test/groovy/graphql/execution/AsyncSerialExecutionStrategyTest.groovy +++ b/src/test/groovy/graphql/execution/AsyncSerialExecutionStrategyTest.groovy @@ -113,7 +113,7 @@ class AsyncSerialExecutionStrategyTest extends Specification { .executionInput(ExecutionInput.newExecutionInput("{}").build()) .profiler(Profiler.NO_OP) .executionInput(ei) - .engineRunningState(new EngineRunningState(ei)) + .engineRunningState(new EngineRunningState(ei, Profiler.NO_OP)) .build() ExecutionStrategyParameters executionStrategyParameters = ExecutionStrategyParameters .newParameters() @@ -163,7 +163,7 @@ class AsyncSerialExecutionStrategyTest extends Specification { .locale(Locale.getDefault()) .graphQLContext(GraphQLContext.getDefault()) .executionInput(ei) - .engineRunningState(new EngineRunningState(ei)) + .engineRunningState(new EngineRunningState(ei, Profiler.NO_OP)) .executionInput(ExecutionInput.newExecutionInput("{}").build()) .profiler(Profiler.NO_OP) .build() diff --git a/src/test/groovy/graphql/execution/ExecutionStrategyTest.groovy b/src/test/groovy/graphql/execution/ExecutionStrategyTest.groovy index 7f7535497a..8ae97cb281 100644 --- a/src/test/groovy/graphql/execution/ExecutionStrategyTest.groovy +++ b/src/test/groovy/graphql/execution/ExecutionStrategyTest.groovy @@ -88,7 +88,7 @@ class ExecutionStrategyTest extends Specification { .locale(Locale.getDefault()) .valueUnboxer(ValueUnboxer.DEFAULT) .profiler(Profiler.NO_OP) - .engineRunningState(new EngineRunningState(ei)) + .engineRunningState(new EngineRunningState(ei, Profiler.NO_OP)) new ExecutionContext(builder) } diff --git a/src/test/groovy/graphql/execution/instrumentation/fieldvalidation/FieldValidationTest.groovy b/src/test/groovy/graphql/execution/instrumentation/fieldvalidation/FieldValidationTest.groovy index ba749fa75b..fc0ae070e6 100644 --- a/src/test/groovy/graphql/execution/instrumentation/fieldvalidation/FieldValidationTest.groovy +++ b/src/test/groovy/graphql/execution/instrumentation/fieldvalidation/FieldValidationTest.groovy @@ -11,7 +11,6 @@ import graphql.execution.AbortExecutionException import graphql.execution.AsyncExecutionStrategy import graphql.execution.Execution import graphql.execution.ExecutionId -import graphql.execution.ResponseMapFactory import graphql.execution.ResultPath import graphql.execution.ValueUnboxer import graphql.execution.instrumentation.ChainedInstrumentation @@ -311,7 +310,7 @@ class FieldValidationTest extends Specification { def execution = new Execution(strategy, strategy, strategy, instrumentation, ValueUnboxer.DEFAULT, false) def executionInput = ExecutionInput.newExecutionInput().query(query).variables(variables).build() - execution.execute(document, schema, ExecutionId.generate(), executionInput, null, new EngineRunningState(executionInput), Profiler.NO_OP) + execution.execute(document, schema, ExecutionId.generate(), executionInput, null, new EngineRunningState(executionInput, Profiler.NO_OP), Profiler.NO_OP) } def "test graphql from end to end with chained instrumentation"() { From f7e31e6cc90b6cec535a83c2a8b887558df49da7 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Wed, 16 Jul 2025 10:49:55 +1000 Subject: [PATCH 12/25] wip --- src/main/java/graphql/ProfilerResult.java | 18 ++++++++---------- src/test/groovy/graphql/ProfilerTest.groovy | 4 ++-- 2 files changed, 10 insertions(+), 12 deletions(-) diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index 9dba350a73..b3e2c28f8e 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -2,6 +2,7 @@ import graphql.execution.ExecutionId; import graphql.language.OperationDefinition; +import graphql.language.OperationDefinition.Operation; import org.jspecify.annotations.NullMarked; import org.jspecify.annotations.Nullable; @@ -38,7 +39,7 @@ public class ProfilerResult { @Nullable private volatile String operationName; @Nullable - private volatile String operationType; + private volatile Operation operationType; private volatile boolean dataLoaderChainingEnabled; private final Set oldStrategyDispatchingAll = ConcurrentHashMap.newKeySet(); private final Set chainedStrategyDispatching = ConcurrentHashMap.newKeySet(); @@ -48,9 +49,8 @@ public class ProfilerResult { public static class DispatchEvent { final String dataLoaderName; - final @Nullable - Integer level; // can be null for delayed dispatching - final int count; + final @Nullable Integer level; // is null for delayed dispatching + final int count; // how many public DispatchEvent(String dataLoaderName, @Nullable Integer level, int count) { this.dataLoaderName = dataLoaderName; @@ -132,7 +132,7 @@ void setTimes(long startTime, long endTime, long engineTotalRunningTime) { void setOperation(OperationDefinition operationDefinition) { this.operationName = operationDefinition.getName(); - this.operationType = operationDefinition.getOperation().name(); + this.operationType = operationDefinition.getOperation(); } void addDataLoaderUsed(String dataLoaderName) { @@ -154,14 +154,12 @@ void addDispatchEvent(String dataLoaderName, @Nullable Integer level, int count) // public getters - public String getOperationName() { - Assert.assertNotNull(operationName); + public @Nullable String getOperationName() { return operationName; } - public String getOperationType() { - Assert.assertNotNull(operationType); - return operationType; + public Operation getOperationType() { + return Assert.assertNotNull(operationType); } public Set getFieldsFetched() { diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index b606763748..2d12bafd3a 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -1,6 +1,6 @@ package graphql - +import graphql.language.OperationDefinition import graphql.schema.DataFetcher import graphql.schema.DataFetchingEnvironment import org.awaitility.Awaitility @@ -205,7 +205,7 @@ class ProfilerTest extends Specification { then: profilerResult.getOperationName() == "MyQuery" - profilerResult.getOperationType() == "QUERY" + profilerResult.getOperationType() == OperationDefinition.Operation.QUERY } From 999bb2f8bd5cdc0de2d2b7a12792785543c617a5 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Wed, 16 Jul 2025 11:41:26 +1000 Subject: [PATCH 13/25] handle non null case --- src/main/java/graphql/GraphQL.java | 3 +-- src/main/java/graphql/Profiler.java | 2 +- src/main/java/graphql/ProfilerImpl.java | 4 ++-- 3 files changed, 4 insertions(+), 5 deletions(-) diff --git a/src/main/java/graphql/GraphQL.java b/src/main/java/graphql/GraphQL.java index af551fbdd5..8de74bd26d 100644 --- a/src/main/java/graphql/GraphQL.java +++ b/src/main/java/graphql/GraphQL.java @@ -9,7 +9,6 @@ import graphql.execution.ExecutionId; import graphql.execution.ExecutionIdProvider; import graphql.execution.ExecutionStrategy; -import graphql.execution.ResponseMapFactory; import graphql.execution.SimpleDataFetcherExceptionHandler; import graphql.execution.SubscriptionExecutionStrategy; import graphql.execution.ValueUnboxer; @@ -482,7 +481,7 @@ public CompletableFuture executeAsync(ExecutionInput executionI EngineRunningState engineRunningState = new EngineRunningState(executionInput, profiler); return engineRunningState.engineRun(() -> { ExecutionInput executionInputWithId = ensureInputHasId(executionInput); - profiler.executionInput(executionInputWithId); + profiler.setExecutionInput(executionInputWithId); engineRunningState.updateExecutionInput(executionInputWithId); CompletableFuture instrumentationStateCF = instrumentation.createStateAsync(new InstrumentationCreateStateParameters(this.graphQLSchema, executionInputWithId)); diff --git a/src/main/java/graphql/Profiler.java b/src/main/java/graphql/Profiler.java index 28b1f966fe..7c15a592f0 100644 --- a/src/main/java/graphql/Profiler.java +++ b/src/main/java/graphql/Profiler.java @@ -17,7 +17,7 @@ public interface Profiler { - default void executionInput(ExecutionInput executionInput) { + default void setExecutionInput(ExecutionInput executionInput) { } diff --git a/src/main/java/graphql/ProfilerImpl.java b/src/main/java/graphql/ProfilerImpl.java index de60b1fb94..457af5ef3b 100644 --- a/src/main/java/graphql/ProfilerImpl.java +++ b/src/main/java/graphql/ProfilerImpl.java @@ -31,8 +31,8 @@ public ProfilerImpl(GraphQLContext graphQLContext) { } @Override - public void executionInput(ExecutionInput executionInput) { - profilerResult.setExecutionId(executionInput.getExecutionId()); + public void setExecutionInput(ExecutionInput executionInput) { + profilerResult.setExecutionId(executionInput.getExecutionIdNonNull()); boolean dataLoaderChainingEnabled = executionInput.getGraphQLContext().getBoolean(DataLoaderDispatchingContextKeys.ENABLE_DATA_LOADER_CHAINING, false); profilerResult.setDataLoaderChainingEnabled(dataLoaderChainingEnabled); } From 5dde0e3a3d9959480e81691752c62ade305a7c25 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Wed, 16 Jul 2025 11:48:12 +1000 Subject: [PATCH 14/25] handle non null case --- src/main/java/graphql/ProfilerImpl.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/main/java/graphql/ProfilerImpl.java b/src/main/java/graphql/ProfilerImpl.java index 457af5ef3b..f6f279e5ad 100644 --- a/src/main/java/graphql/ProfilerImpl.java +++ b/src/main/java/graphql/ProfilerImpl.java @@ -70,7 +70,7 @@ public EngineRunningObserver wrapEngineRunningObserver(@Nullable EngineRunningOb // nothing to wrap here return new EngineRunningObserver() { @Override - public void runningStateChanged(ExecutionId executionId, GraphQLContext graphQLContext, RunningState runningState) { + public void runningStateChanged(@Nullable ExecutionId executionId, GraphQLContext graphQLContext, RunningState runningState) { runningStateChangedImpl(executionId, graphQLContext, runningState); if (engineRunningObserver != null) { engineRunningObserver.runningStateChanged(executionId, graphQLContext, runningState); @@ -79,7 +79,7 @@ public void runningStateChanged(ExecutionId executionId, GraphQLContext graphQLC }; } - private void runningStateChangedImpl(ExecutionId executionId, GraphQLContext graphQLContext, EngineRunningObserver.RunningState runningState) { + private void runningStateChangedImpl(@Nullable ExecutionId executionId, GraphQLContext graphQLContext, EngineRunningObserver.RunningState runningState) { long now = System.nanoTime(); if (runningState == EngineRunningObserver.RunningState.RUNNING_START) { startTime = now; From 4a47b9d4e8348eac725977c16de98289e052d131 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Thu, 17 Jul 2025 14:33:11 +1000 Subject: [PATCH 15/25] add Map specific summary methods --- src/main/java/graphql/ProfilerResult.java | 33 +++++++++++++++++++++++ 1 file changed, 33 insertions(+) diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index b3e2c28f8e..871b1b4e39 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -8,6 +8,7 @@ import java.util.ArrayList; import java.util.Collections; +import java.util.LinkedHashMap; import java.util.LinkedHashSet; import java.util.List; import java.util.Map; @@ -282,6 +283,26 @@ public String shortSummary() { } + public Map shortSummaryMap() { + Map result = new LinkedHashMap<>(); + result.put("executionId", Assert.assertNotNull(executionId)); + result.put("operation", operationType + ":" + operationName); + result.put("startTime", startTime); + result.put("endTime", endTime); + result.put("totalRunTime", (endTime - startTime) + "(" + (endTime - startTime) / 1_000_000 + "ms)"); + result.put("engineTotalRunningTime", engineTotalRunningTime + "(" + engineTotalRunningTime / 1_000_000 + "ms)"); + result.put("totalDataFetcherInvocations", totalDataFetcherInvocations); + result.put("totalPropertyDataFetcherInvocations", totalPropertyDataFetcherInvocations); + result.put("fieldsFetchedCount", fieldsFetched.size()); + result.put("dataLoaderChainingEnabled", dataLoaderChainingEnabled); + result.put("dataLoaderLoadInvocations", dataLoaderLoadInvocations); + result.put("oldStrategyDispatchingAll", oldStrategyDispatchingAll); + result.put("chainedStrategyDispatching", chainedStrategyDispatching); + result.put("dispatchEvents", getDispatchEventsAsMap()); + return result; + } + + private String printDispatchEvents() { if (dispatchEvents.isEmpty()) { return "[]"; @@ -303,6 +324,18 @@ private String printDispatchEvents() { return sb.toString(); } + public List> getDispatchEventsAsMap() { + List> result = new ArrayList<>(); + for (DispatchEvent event : dispatchEvents) { + Map eventMap = new LinkedHashMap<>(); + eventMap.put("dataLoader", event.getDataLoaderName()); + eventMap.put("level", event.getLevel() != null ? event.getLevel() : "delayed"); + eventMap.put("count", event.getCount()); + result.add(eventMap); + } + return result; + } + @Override public String toString() { return shortSummary(); From 0b7c15bcd440f35638e3d2431832199b54ce87a8 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Fri, 18 Jul 2025 07:50:54 +1000 Subject: [PATCH 16/25] collect instrumentations --- src/main/java/graphql/GraphQL.java | 17 ++++--- src/main/java/graphql/Profiler.java | 4 +- src/main/java/graphql/ProfilerImpl.java | 23 +++++++++- src/main/java/graphql/ProfilerResult.java | 30 ++++++++++--- .../InstrumentationContext.java | 5 ++- src/test/groovy/graphql/ProfilerTest.groovy | 44 +++++++++++++++++++ 6 files changed, 106 insertions(+), 17 deletions(-) diff --git a/src/main/java/graphql/GraphQL.java b/src/main/java/graphql/GraphQL.java index 8de74bd26d..16d14ab4b9 100644 --- a/src/main/java/graphql/GraphQL.java +++ b/src/main/java/graphql/GraphQL.java @@ -26,10 +26,11 @@ import graphql.language.Document; import graphql.schema.GraphQLSchema; import graphql.validation.ValidationError; +import org.jspecify.annotations.NullMarked; +import org.jspecify.annotations.NullUnmarked; import java.util.List; import java.util.Locale; -import java.util.Optional; import java.util.concurrent.CompletableFuture; import java.util.concurrent.CompletionException; import java.util.concurrent.atomic.AtomicReference; @@ -82,6 +83,7 @@ */ @SuppressWarnings("Duplicates") @PublicApi +@NullMarked public class GraphQL { /** @@ -258,9 +260,9 @@ public GraphQL transform(Consumer builderConsumer) { .queryExecutionStrategy(this.queryStrategy) .mutationExecutionStrategy(this.mutationStrategy) .subscriptionExecutionStrategy(this.subscriptionStrategy) - .executionIdProvider(Optional.ofNullable(this.idProvider).orElse(builder.idProvider)) - .instrumentation(Optional.ofNullable(this.instrumentation).orElse(builder.instrumentation)) - .preparsedDocumentProvider(Optional.ofNullable(this.preparsedDocumentProvider).orElse(builder.preparsedDocumentProvider)); + .executionIdProvider(this.idProvider) + .instrumentation(this.instrumentation) + .preparsedDocumentProvider(this.preparsedDocumentProvider); builderConsumer.accept(builder); @@ -268,6 +270,7 @@ public GraphQL transform(Consumer builderConsumer) { } @PublicApi + @NullUnmarked public static class Builder { private GraphQLSchema graphQLSchema; private ExecutionStrategy queryExecutionStrategy; @@ -481,7 +484,7 @@ public CompletableFuture executeAsync(ExecutionInput executionI EngineRunningState engineRunningState = new EngineRunningState(executionInput, profiler); return engineRunningState.engineRun(() -> { ExecutionInput executionInputWithId = ensureInputHasId(executionInput); - profiler.setExecutionInput(executionInputWithId); + profiler.setExecutionInputAndInstrumentation(executionInputWithId, instrumentation); engineRunningState.updateExecutionInput(executionInputWithId); CompletableFuture instrumentationStateCF = instrumentation.createStateAsync(new InstrumentationCreateStateParameters(this.graphQLSchema, executionInputWithId)); @@ -543,7 +546,7 @@ private CompletableFuture parseValidateAndExecute(ExecutionInpu return CompletableFuture.completedFuture(new ExecutionResultImpl(preparsedDocumentEntry.getErrors())); } try { - return execute(executionInputRef.get(), preparsedDocumentEntry.getDocument(), graphQLSchema, instrumentationState, engineRunningState, profiler); + return execute(Assert.assertNotNull(executionInputRef.get()), preparsedDocumentEntry.getDocument(), graphQLSchema, instrumentationState, engineRunningState, profiler); } catch (AbortExecutionException e) { return CompletableFuture.completedFuture(e.toExecutionResult()); } @@ -552,7 +555,7 @@ private CompletableFuture parseValidateAndExecute(ExecutionInpu private PreparsedDocumentEntry parseAndValidate(AtomicReference executionInputRef, GraphQLSchema graphQLSchema, InstrumentationState instrumentationState) { - ExecutionInput executionInput = executionInputRef.get(); + ExecutionInput executionInput = assertNotNull(executionInputRef.get()); ParseAndValidateResult parseResult = parse(executionInput, graphQLSchema, instrumentationState); if (parseResult.isFailure()) { diff --git a/src/main/java/graphql/Profiler.java b/src/main/java/graphql/Profiler.java index 7c15a592f0..8f2b457eaf 100644 --- a/src/main/java/graphql/Profiler.java +++ b/src/main/java/graphql/Profiler.java @@ -2,6 +2,7 @@ import graphql.execution.EngineRunningObserver; import graphql.execution.ResultPath; +import graphql.execution.instrumentation.Instrumentation; import graphql.language.OperationDefinition; import graphql.schema.DataFetcher; import org.jspecify.annotations.NullMarked; @@ -16,8 +17,7 @@ public interface Profiler { }; - - default void setExecutionInput(ExecutionInput executionInput) { + default void setExecutionInputAndInstrumentation(ExecutionInput executionInput, Instrumentation instrumentation) { } diff --git a/src/main/java/graphql/ProfilerImpl.java b/src/main/java/graphql/ProfilerImpl.java index f6f279e5ad..0197c4dcd6 100644 --- a/src/main/java/graphql/ProfilerImpl.java +++ b/src/main/java/graphql/ProfilerImpl.java @@ -3,6 +3,8 @@ import graphql.execution.EngineRunningObserver; import graphql.execution.ExecutionId; import graphql.execution.ResultPath; +import graphql.execution.instrumentation.ChainedInstrumentation; +import graphql.execution.instrumentation.Instrumentation; import graphql.execution.instrumentation.dataloader.DataLoaderDispatchingContextKeys; import graphql.language.OperationDefinition; import graphql.schema.DataFetcher; @@ -11,6 +13,8 @@ import org.jspecify.annotations.NullMarked; import org.jspecify.annotations.Nullable; +import java.util.ArrayList; +import java.util.List; import java.util.concurrent.CompletableFuture; import java.util.concurrent.atomic.AtomicLong; @@ -23,18 +27,33 @@ public class ProfilerImpl implements Profiler { private volatile long lastStartTime; private final AtomicLong engineTotalRunningTime = new AtomicLong(); - final ProfilerResult profilerResult = new ProfilerResult(); public ProfilerImpl(GraphQLContext graphQLContext) { + // No real work can happen here, since the engine didn't "officially" start yet. graphQLContext.put(ProfilerResult.PROFILER_CONTEXT_KEY, profilerResult); } @Override - public void setExecutionInput(ExecutionInput executionInput) { + public void setExecutionInputAndInstrumentation(ExecutionInput executionInput, Instrumentation instrumentation) { profilerResult.setExecutionId(executionInput.getExecutionIdNonNull()); boolean dataLoaderChainingEnabled = executionInput.getGraphQLContext().getBoolean(DataLoaderDispatchingContextKeys.ENABLE_DATA_LOADER_CHAINING, false); profilerResult.setDataLoaderChainingEnabled(dataLoaderChainingEnabled); + + List instrumentationClasses = new ArrayList<>(); + collectInstrumentationClasses(instrumentationClasses, instrumentation); + profilerResult.setInstrumentationClasses(instrumentationClasses); + } + + private void collectInstrumentationClasses(List result, Instrumentation instrumentation) { + if (instrumentation instanceof ChainedInstrumentation) { + ChainedInstrumentation chainedInstrumentation = (ChainedInstrumentation) instrumentation; + for (Instrumentation child : chainedInstrumentation.getInstrumentations()) { + collectInstrumentationClasses(result, child); + } + } else { + result.add(instrumentation.getClass().getName()); + } } @Override diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index 871b1b4e39..7c469acdc8 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -29,14 +29,10 @@ public class ProfilerResult { private long engineTotalRunningTime; private final AtomicInteger totalDataFetcherInvocations = new AtomicInteger(); private final AtomicInteger totalPropertyDataFetcherInvocations = new AtomicInteger(); - private final Set fieldsFetched = ConcurrentHashMap.newKeySet(); - - private final Map dataFetcherInvocationCount = new ConcurrentHashMap<>(); + // this is the count of how many times a data loader was invoked per data loader name private final Map dataLoaderLoadInvocations = new ConcurrentHashMap<>(); - private final Map dataFetcherTypeMap = new ConcurrentHashMap<>(); - private final Map dataFetcherResultType = new ConcurrentHashMap<>(); @Nullable private volatile String operationName; @Nullable @@ -45,8 +41,27 @@ public class ProfilerResult { private final Set oldStrategyDispatchingAll = ConcurrentHashMap.newKeySet(); private final Set chainedStrategyDispatching = ConcurrentHashMap.newKeySet(); + private final List instrumentationClasses = Collections.synchronizedList(new ArrayList<>()); + private final List dispatchEvents = Collections.synchronizedList(new ArrayList<>()); + /** + * the following fields can contain a lot of data for large requests + */ + // all fields fetched during the execution, key is the field path + private final Set fieldsFetched = ConcurrentHashMap.newKeySet(); + // this is the count of how many times a data fetcher was invoked per field + private final Map dataFetcherInvocationCount = new ConcurrentHashMap<>(); + // the type of the data fetcher per field, key is the field path + private final Map dataFetcherTypeMap = new ConcurrentHashMap<>(); + // the type of the data fetcher result field, key is the field path + // in theory different DataFetcher invocations can return different types, but we only record the first one + private final Map dataFetcherResultType = new ConcurrentHashMap<>(); + + public void setInstrumentationClasses(List instrumentationClasses) { + this.instrumentationClasses.addAll(instrumentationClasses); + } + public static class DispatchEvent { final String dataLoaderName; @@ -240,6 +255,10 @@ public List getDispatchEvents() { return dispatchEvents; } + public List getInstrumentationClasses() { + return instrumentationClasses; + } + public String fullSummary() { return "ProfilerResult{" + "executionId=" + executionId + @@ -299,6 +318,7 @@ public Map shortSummaryMap() { result.put("oldStrategyDispatchingAll", oldStrategyDispatchingAll); result.put("chainedStrategyDispatching", chainedStrategyDispatching); result.put("dispatchEvents", getDispatchEventsAsMap()); + result.put("instrumentationClasses", instrumentationClasses); return result; } diff --git a/src/main/java/graphql/execution/instrumentation/InstrumentationContext.java b/src/main/java/graphql/execution/instrumentation/InstrumentationContext.java index 4058f2f38b..422d0ece71 100644 --- a/src/main/java/graphql/execution/instrumentation/InstrumentationContext.java +++ b/src/main/java/graphql/execution/instrumentation/InstrumentationContext.java @@ -1,6 +1,8 @@ package graphql.execution.instrumentation; import graphql.PublicSpi; +import org.jspecify.annotations.NullMarked; +import org.jspecify.annotations.Nullable; /** * When a {@link Instrumentation}.'beginXXX()' method is called then it must return a non null InstrumentationContext @@ -11,6 +13,7 @@ * just happened or "loggers" to be called to record what has happened. */ @PublicSpi +@NullMarked public interface InstrumentationContext { /** @@ -24,6 +27,6 @@ public interface InstrumentationContext { * @param result the result of the step (which may be null) * @param t this exception will be non null if an exception was thrown during the step */ - void onCompleted(T result, Throwable t); + void onCompleted(@Nullable T result, @Nullable Throwable t); } diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index 2d12bafd3a..dd30d7b93e 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -1,5 +1,8 @@ package graphql +import graphql.execution.instrumentation.ChainedInstrumentation +import graphql.execution.instrumentation.Instrumentation +import graphql.execution.instrumentation.SimplePerformantInstrumentation import graphql.language.OperationDefinition import graphql.schema.DataFetcher import graphql.schema.DataFetchingEnvironment @@ -51,6 +54,47 @@ class ProfilerTest extends Specification { } + def "collects instrumentation list"() { + given: + def sdl = ''' + type Query { + hello: String + } + ''' + def schema = TestUtil.schema(sdl, [Query: [ + hello: { DataFetchingEnvironment dfe -> return "world" } as DataFetcher + ]]) + Instrumentation fooInstrumentation = new Instrumentation() {}; + Instrumentation barInstrumentation = new Instrumentation() {}; + ChainedInstrumentation chainedInstrumentation = new ChainedInstrumentation( + new ChainedInstrumentation(new SimplePerformantInstrumentation()), + new ChainedInstrumentation(fooInstrumentation, barInstrumentation), + new SimplePerformantInstrumentation()) + + + def graphql = GraphQL.newGraphQL(schema).instrumentation(chainedInstrumentation).build(); + + ExecutionInput ei = ExecutionInput.newExecutionInput() + .query("{ hello }") + .profileExecution(true) + .build() + + when: + def result = graphql.execute(ei) + def profilerResult = ei.getGraphQLContext().get(ProfilerResult.PROFILER_CONTEXT_KEY) as ProfilerResult + + then: + result.getData() == [hello: "world"] + + then: + profilerResult.getInstrumentationClasses() == ["graphql.execution.instrumentation.SimplePerformantInstrumentation", + "graphql.ProfilerTest\$1", + "graphql.ProfilerTest\$2", + "graphql.execution.instrumentation.SimplePerformantInstrumentation"] + + } + + def "two DF with list"() { given: def sdl = ''' From e6faa185b172ee9dbee1c8a1b4cd39aa3bc4a602 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Fri, 18 Jul 2025 12:37:09 +1000 Subject: [PATCH 17/25] manual dispatch collected --- src/main/java/graphql/Profiler.java | 6 +- src/main/java/graphql/ProfilerImpl.java | 11 +++- src/main/java/graphql/ProfilerResult.java | 23 ++++++-- .../graphql/schema/DataLoaderWithContext.java | 12 ++++ src/test/groovy/graphql/ProfilerTest.groovy | 56 +++++++++++++++++++ 5 files changed, 99 insertions(+), 9 deletions(-) diff --git a/src/main/java/graphql/Profiler.java b/src/main/java/graphql/Profiler.java index 8f2b457eaf..1a206a10c1 100644 --- a/src/main/java/graphql/Profiler.java +++ b/src/main/java/graphql/Profiler.java @@ -51,7 +51,11 @@ default void batchLoadedOldStrategy(String name, int level, int count) { } - default void batchLoadedNewStrategy(String name, @Nullable Integer level, int count) { + default void batchLoadedNewStrategy(String dataLoaderName, @Nullable Integer level, int count) { + + } + + default void manualDispatch(String dataLoaderName, int level, int count) { } } diff --git a/src/main/java/graphql/ProfilerImpl.java b/src/main/java/graphql/ProfilerImpl.java index 0197c4dcd6..4f423d21f0 100644 --- a/src/main/java/graphql/ProfilerImpl.java +++ b/src/main/java/graphql/ProfilerImpl.java @@ -138,11 +138,16 @@ public void oldStrategyDispatchingAll(int level) { @Override public void batchLoadedOldStrategy(String name, int level, int count) { - profilerResult.addDispatchEvent(name, level, count); + profilerResult.addDispatchEvent(name, level, count, ProfilerResult.DispatchEventType.STRATEGY_DISPATCH); } @Override - public void batchLoadedNewStrategy(String name, @Nullable Integer level, int count) { - profilerResult.addDispatchEvent(name, level, count); + public void batchLoadedNewStrategy(String dataLoaderName, @Nullable Integer level, int count) { + profilerResult.addDispatchEvent(dataLoaderName, level, count, ProfilerResult.DispatchEventType.STRATEGY_DISPATCH); + } + + @Override + public void manualDispatch(String dataLoaderName, int level, int count) { + profilerResult.addDispatchEvent(dataLoaderName, level, count, ProfilerResult.DispatchEventType.MANUAL_DISPATCH); } } diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index 7c469acdc8..715f6df3a5 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -63,15 +63,22 @@ public void setInstrumentationClasses(List instrumentationClasses) { } + public enum DispatchEventType { + STRATEGY_DISPATCH, + MANUAL_DISPATCH, + } + public static class DispatchEvent { final String dataLoaderName; final @Nullable Integer level; // is null for delayed dispatching final int count; // how many + final DispatchEventType type; - public DispatchEvent(String dataLoaderName, @Nullable Integer level, int count) { + public DispatchEvent(String dataLoaderName, @Nullable Integer level, int count, DispatchEventType type) { this.dataLoaderName = dataLoaderName; this.level = level; this.count = count; + this.type = type; } public String getDataLoaderName() { @@ -86,10 +93,15 @@ public int getCount() { return count; } + public DispatchEventType getType() { + return type; + } + @Override public String toString() { return "DispatchEvent{" + - "dataLoaderName='" + dataLoaderName + '\'' + + "type=" + type + + ", dataLoaderName='" + dataLoaderName + '\'' + ", level=" + level + ", count=" + count + '}'; @@ -164,8 +176,8 @@ void chainedStrategyDispatching(int level) { chainedStrategyDispatching.add(level); } - void addDispatchEvent(String dataLoaderName, @Nullable Integer level, int count) { - dispatchEvents.add(new DispatchEvent(dataLoaderName, level, count)); + void addDispatchEvent(String dataLoaderName, @Nullable Integer level, int count, DispatchEventType type) { + dispatchEvents.add(new DispatchEvent(dataLoaderName, level, count, type)); } // public getters @@ -358,6 +370,7 @@ public List> getDispatchEventsAsMap() { @Override public String toString() { - return shortSummary(); + return "ProfilerResult" + shortSummaryMap(); } + } diff --git a/src/main/java/graphql/schema/DataLoaderWithContext.java b/src/main/java/graphql/schema/DataLoaderWithContext.java index 45fa5dfae8..ca384eda46 100644 --- a/src/main/java/graphql/schema/DataLoaderWithContext.java +++ b/src/main/java/graphql/schema/DataLoaderWithContext.java @@ -9,6 +9,7 @@ import org.jspecify.annotations.NullMarked; import org.jspecify.annotations.Nullable; +import java.util.List; import java.util.concurrent.CompletableFuture; @Internal @@ -40,4 +41,15 @@ public CompletableFuture load(@NonNull K key, @Nullable Object keyContext) { return result; } + @Override + public CompletableFuture> dispatch() { + CompletableFuture> dispatchResult = delegate.dispatch(); + dispatchResult.whenComplete((result, error) -> { + if (result != null) { + DataFetchingEnvironmentImpl.DFEInternalState dfeInternalState = (DataFetchingEnvironmentImpl.DFEInternalState) dfe.toInternal(); + dfeInternalState.getProfiler().manualDispatch(dataLoaderName, dfe.getExecutionStepInfo().getPath().getLevel(), result.size()); + } + }); + return dispatchResult; + } } diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index dd30d7b93e..ef718c734d 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -15,6 +15,7 @@ import spock.lang.Specification import java.time.Duration import java.util.concurrent.CompletableFuture +import java.util.concurrent.atomic.AtomicInteger import static graphql.ExecutionInput.newExecutionInput import static graphql.ProfilerResult.DataFetcherResultType.COMPLETABLE_FUTURE_COMPLETED @@ -54,6 +55,61 @@ class ProfilerTest extends Specification { } + def "manual dataloader dispatch"() { + given: + def sdl = ''' + + type Query { + dog: String + } + ''' + AtomicInteger batchLoadCalls = new AtomicInteger() + BatchLoader batchLoader = { keys -> + return supplyAsync { + batchLoadCalls.incrementAndGet() + Thread.sleep(250) + println "BatchLoader called with keys: $keys" + return ["Luna"] + } + } + + DataLoader nameDataLoader = DataLoaderFactory.newDataLoader(batchLoader); + + DataLoaderRegistry dataLoaderRegistry = new DataLoaderRegistry(); + dataLoaderRegistry.register("name", nameDataLoader); + + def df1 = { env -> + def loader = env.getDataLoader("name") + def result = loader.load("Key1") + loader.dispatch() + return result + } as DataFetcher + + def fetchers = ["Query": ["dog": df1]] + def schema = TestUtil.schema(sdl, fetchers) + def graphQL = GraphQL.newGraphQL(schema).build() + + def query = "{ dog } " + def ei = newExecutionInput(query).dataLoaderRegistry(dataLoaderRegistry).profileExecution(true).build() + setEnableDataLoaderChaining(ei.graphQLContext, true) + + when: + def efCF = graphQL.executeAsync(ei) + Awaitility.await().until { efCF.isDone() } + def er = efCF.get() + def profilerResult = ei.getGraphQLContext().get(ProfilerResult.PROFILER_CONTEXT_KEY) as ProfilerResult + then: + er.data == [dog: "Luna"] + batchLoadCalls.get() == 1 + then: + profilerResult.getDispatchEvents()[0].type == ProfilerResult.DispatchEventType.MANUAL_DISPATCH + profilerResult.getDispatchEvents()[0].dataLoaderName == "name" + profilerResult.getDispatchEvents()[0].count == 1 + profilerResult.getDispatchEvents()[0].level == 1 + + } + + def "collects instrumentation list"() { given: def sdl = ''' From 0ab88dae7e6272b8b77938fc4ae3cccba60c9239 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Fri, 18 Jul 2025 16:25:38 +1000 Subject: [PATCH 18/25] wip --- src/main/java/graphql/ProfilerResult.java | 1 + .../graphql/schema/DataLoaderWithContext.java | 2 +- src/test/groovy/graphql/ProfilerTest.groovy | 66 +++++++++++++++++++ 3 files changed, 68 insertions(+), 1 deletion(-) diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index 715f6df3a5..b43d0131fc 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -360,6 +360,7 @@ public List> getDispatchEventsAsMap() { List> result = new ArrayList<>(); for (DispatchEvent event : dispatchEvents) { Map eventMap = new LinkedHashMap<>(); + eventMap.put("type", event.getType().name()); eventMap.put("dataLoader", event.getDataLoaderName()); eventMap.put("level", event.getLevel() != null ? event.getLevel() : "delayed"); eventMap.put("count", event.getCount()); diff --git a/src/main/java/graphql/schema/DataLoaderWithContext.java b/src/main/java/graphql/schema/DataLoaderWithContext.java index ca384eda46..b985a8eafc 100644 --- a/src/main/java/graphql/schema/DataLoaderWithContext.java +++ b/src/main/java/graphql/schema/DataLoaderWithContext.java @@ -45,7 +45,7 @@ public CompletableFuture load(@NonNull K key, @Nullable Object keyContext) { public CompletableFuture> dispatch() { CompletableFuture> dispatchResult = delegate.dispatch(); dispatchResult.whenComplete((result, error) -> { - if (result != null) { + if (result != null && result.size() > 0) { DataFetchingEnvironmentImpl.DFEInternalState dfeInternalState = (DataFetchingEnvironmentImpl.DFEInternalState) dfe.toInternal(); dfeInternalState.getProfiler().manualDispatch(dataLoaderName, dfe.getExecutionStepInfo().getPath().getLevel(), result.size()); } diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index ef718c734d..e4a3114324 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -109,6 +109,72 @@ class ProfilerTest extends Specification { } + def "cached dataloader values"() { + given: + def sdl = ''' + + type Query { + dog: Dog + } + type Dog { + name: String + } + ''' + AtomicInteger batchLoadCalls = new AtomicInteger() + BatchLoader batchLoader = { keys -> + return supplyAsync { + batchLoadCalls.incrementAndGet() + Thread.sleep(250) + println "BatchLoader called with keys: $keys" + return ["Luna"] + } + } + + DataLoader nameDataLoader = DataLoaderFactory.newDataLoader(batchLoader); + + DataLoaderRegistry dataLoaderRegistry = new DataLoaderRegistry(); + dataLoaderRegistry.register("name", nameDataLoader); + + def dogDF = { env -> + def loader = env.getDataLoader("name") + def result = loader.load("Key1").thenCompose { + return loader.load("Key1") // This should hit the cache + } + } as DataFetcher + + def nameDF = { env -> + def loader = env.getDataLoader("name") + def result = loader.load("Key1").thenCompose { + return loader.load("Key1") // This should hit the cache + } + } as DataFetcher + + + def fetchers = [Query: [dog: dogDF], Dog: [name: nameDF]] + def schema = TestUtil.schema(sdl, fetchers) + def graphQL = GraphQL.newGraphQL(schema).build() + + def query = "{ dog {name } } " + def ei = newExecutionInput(query).dataLoaderRegistry(dataLoaderRegistry).profileExecution(true).build() + setEnableDataLoaderChaining(ei.graphQLContext, true) + + when: + def efCF = graphQL.executeAsync(ei) + Awaitility.await().until { efCF.isDone() } + def er = efCF.get() + def profilerResult = ei.getGraphQLContext().get(ProfilerResult.PROFILER_CONTEXT_KEY) as ProfilerResult + then: + er.data == [dog: [name: "Luna"]] + batchLoadCalls.get() == 1 + then: + profilerResult.getDataLoaderLoadInvocations().get("name") == 4 + profilerResult.getDispatchEvents()[0].type == ProfilerResult.DispatchEventType.STRATEGY_DISPATCH + profilerResult.getDispatchEvents()[0].dataLoaderName == "name" + profilerResult.getDispatchEvents()[0].count == 1 + profilerResult.getDispatchEvents()[0].level == 1 + + } + def "collects instrumentation list"() { given: From 8bcdef830a5af4d5f0ccaf61aedc56755903fb17 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Fri, 18 Jul 2025 16:29:05 +1000 Subject: [PATCH 19/25] wip --- src/main/java/graphql/Profiler.java | 4 ---- src/main/java/graphql/ProfilerImpl.java | 5 ----- src/main/java/graphql/ProfilerResult.java | 10 ---------- .../dataloader/PerLevelDataLoaderDispatchStrategy.java | 1 - src/test/groovy/graphql/ProfilerTest.groovy | 1 - 5 files changed, 21 deletions(-) diff --git a/src/main/java/graphql/Profiler.java b/src/main/java/graphql/Profiler.java index 1a206a10c1..e43b59a0bd 100644 --- a/src/main/java/graphql/Profiler.java +++ b/src/main/java/graphql/Profiler.java @@ -42,10 +42,6 @@ default void oldStrategyDispatchingAll(int level) { } - default void chainedStrategyDispatching(int level) { - - } - default void batchLoadedOldStrategy(String name, int level, int count) { diff --git a/src/main/java/graphql/ProfilerImpl.java b/src/main/java/graphql/ProfilerImpl.java index 4f423d21f0..1a062c8b26 100644 --- a/src/main/java/graphql/ProfilerImpl.java +++ b/src/main/java/graphql/ProfilerImpl.java @@ -126,11 +126,6 @@ public void dataLoaderUsed(String dataLoaderName) { profilerResult.addDataLoaderUsed(dataLoaderName); } - @Override - public void chainedStrategyDispatching(int level) { - profilerResult.chainedStrategyDispatching(level); - } - @Override public void oldStrategyDispatchingAll(int level) { profilerResult.oldStrategyDispatchingAll(level); diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index b43d0131fc..bca9e798df 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -39,7 +39,6 @@ public class ProfilerResult { private volatile Operation operationType; private volatile boolean dataLoaderChainingEnabled; private final Set oldStrategyDispatchingAll = ConcurrentHashMap.newKeySet(); - private final Set chainedStrategyDispatching = ConcurrentHashMap.newKeySet(); private final List instrumentationClasses = Collections.synchronizedList(new ArrayList<>()); @@ -172,9 +171,6 @@ void oldStrategyDispatchingAll(int level) { } - void chainedStrategyDispatching(int level) { - chainedStrategyDispatching.add(level); - } void addDispatchEvent(String dataLoaderName, @Nullable Integer level, int count, DispatchEventType type) { dispatchEvents.add(new DispatchEvent(dataLoaderName, level, count, type)); @@ -251,9 +247,6 @@ public Map getDataLoaderLoadInvocations() { return dataLoaderLoadInvocations; } - public Set getChainedStrategyDispatching() { - return chainedStrategyDispatching; - } public Set getOldStrategyDispatchingAll() { return oldStrategyDispatchingAll; @@ -288,7 +281,6 @@ public String fullSummary() { ", dataLoaderChainingEnabled=" + dataLoaderChainingEnabled + ", dataLoaderLoadInvocations=" + dataLoaderLoadInvocations + ", oldStrategyDispatchingAll=" + oldStrategyDispatchingAll + - ", chainedStrategyDispatching=" + chainedStrategyDispatching + ", dispatchEvents=" + printDispatchEvents() + '}'; } @@ -307,7 +299,6 @@ public String shortSummary() { ", dataLoaderChainingEnabled=" + dataLoaderChainingEnabled + ", dataLoaderLoadInvocations=" + dataLoaderLoadInvocations + ", oldStrategyDispatchingAll=" + oldStrategyDispatchingAll + - ", chainedStrategyDispatching=" + chainedStrategyDispatching + ", dispatchEvents=" + printDispatchEvents() + '}'; @@ -328,7 +319,6 @@ public Map shortSummaryMap() { result.put("dataLoaderChainingEnabled", dataLoaderChainingEnabled); result.put("dataLoaderLoadInvocations", dataLoaderLoadInvocations); result.put("oldStrategyDispatchingAll", oldStrategyDispatchingAll); - result.put("chainedStrategyDispatching", chainedStrategyDispatching); result.put("dispatchEvents", getDispatchEventsAsMap()); result.put("instrumentationClasses", instrumentationClasses); return result; diff --git a/src/main/java/graphql/execution/instrumentation/dataloader/PerLevelDataLoaderDispatchStrategy.java b/src/main/java/graphql/execution/instrumentation/dataloader/PerLevelDataLoaderDispatchStrategy.java index 83f6ac9e7c..efc5a98073 100644 --- a/src/main/java/graphql/execution/instrumentation/dataloader/PerLevelDataLoaderDispatchStrategy.java +++ b/src/main/java/graphql/execution/instrumentation/dataloader/PerLevelDataLoaderDispatchStrategy.java @@ -495,7 +495,6 @@ void dispatch(int level, CallStack callStack) { } Set resultPathWithDataLoaders = callStack.levelToResultPathWithDataLoader.get(level); if (resultPathWithDataLoaders != null) { - profiler.chainedStrategyDispatching(level); Set resultPathToDispatch = callStack.lock.callLocked(() -> { callStack.dispatchingStartedPerLevel.add(level); return resultPathWithDataLoaders diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index e4a3114324..a5c7874966 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -437,7 +437,6 @@ class ProfilerTest extends Specification { batchLoadCalls == 2 profilerResult.isDataLoaderChainingEnabled() profilerResult.getDataLoaderLoadInvocations() == [name: 4] - profilerResult.getChainedStrategyDispatching() == [1] as Set profilerResult.getDispatchEvents().size() == 2 profilerResult.getDispatchEvents()[0].dataLoaderName == "name" profilerResult.getDispatchEvents()[0].level == 1 From 62f1e84045cc9cd7fab5a87639785919eba4460f Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Fri, 18 Jul 2025 17:06:14 +1000 Subject: [PATCH 20/25] improve naming --- src/main/java/graphql/ProfilerResult.java | 16 ++++++++-------- src/test/groovy/graphql/ProfilerTest.groovy | 8 ++++---- 2 files changed, 12 insertions(+), 12 deletions(-) diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index bca9e798df..a5071f05e8 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -70,13 +70,13 @@ public enum DispatchEventType { public static class DispatchEvent { final String dataLoaderName; final @Nullable Integer level; // is null for delayed dispatching - final int count; // how many + final int keyCount; // how many final DispatchEventType type; - public DispatchEvent(String dataLoaderName, @Nullable Integer level, int count, DispatchEventType type) { + public DispatchEvent(String dataLoaderName, @Nullable Integer level, int keyCount, DispatchEventType type) { this.dataLoaderName = dataLoaderName; this.level = level; - this.count = count; + this.keyCount = keyCount; this.type = type; } @@ -88,8 +88,8 @@ public String getDataLoaderName() { return level; } - public int getCount() { - return count; + public int getKeyCount() { + return keyCount; } public DispatchEventType getType() { @@ -102,7 +102,7 @@ public String toString() { "type=" + type + ", dataLoaderName='" + dataLoaderName + '\'' + ", level=" + level + - ", count=" + count + + ", keyCount=" + keyCount + '}'; } } @@ -337,7 +337,7 @@ private String printDispatchEvents() { .append(event.getDataLoaderName()) .append(", level=") .append(event.getLevel()) - .append(", count=").append(event.getCount()); + .append(", count=").append(event.getKeyCount()); if (i++ < dispatchEvents.size() - 1) { sb.append("; "); } @@ -353,7 +353,7 @@ public List> getDispatchEventsAsMap() { eventMap.put("type", event.getType().name()); eventMap.put("dataLoader", event.getDataLoaderName()); eventMap.put("level", event.getLevel() != null ? event.getLevel() : "delayed"); - eventMap.put("count", event.getCount()); + eventMap.put("keyCount", event.getKeyCount()); result.add(eventMap); } return result; diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index a5c7874966..f671898c0d 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -104,7 +104,7 @@ class ProfilerTest extends Specification { then: profilerResult.getDispatchEvents()[0].type == ProfilerResult.DispatchEventType.MANUAL_DISPATCH profilerResult.getDispatchEvents()[0].dataLoaderName == "name" - profilerResult.getDispatchEvents()[0].count == 1 + profilerResult.getDispatchEvents()[0].keyCount == 1 profilerResult.getDispatchEvents()[0].level == 1 } @@ -170,7 +170,7 @@ class ProfilerTest extends Specification { profilerResult.getDataLoaderLoadInvocations().get("name") == 4 profilerResult.getDispatchEvents()[0].type == ProfilerResult.DispatchEventType.STRATEGY_DISPATCH profilerResult.getDispatchEvents()[0].dataLoaderName == "name" - profilerResult.getDispatchEvents()[0].count == 1 + profilerResult.getDispatchEvents()[0].keyCount == 1 profilerResult.getDispatchEvents()[0].level == 1 } @@ -440,10 +440,10 @@ class ProfilerTest extends Specification { profilerResult.getDispatchEvents().size() == 2 profilerResult.getDispatchEvents()[0].dataLoaderName == "name" profilerResult.getDispatchEvents()[0].level == 1 - profilerResult.getDispatchEvents()[0].count == 2 + profilerResult.getDispatchEvents()[0].keyCount == 2 profilerResult.getDispatchEvents()[1].dataLoaderName == "name" profilerResult.getDispatchEvents()[1].level == 1 - profilerResult.getDispatchEvents()[1].count == 2 + profilerResult.getDispatchEvents()[1].keyCount == 2 } From 76cdbc1937b598e9765abeb5bd776236d17c3b62 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Sat, 19 Jul 2025 08:45:54 +1000 Subject: [PATCH 21/25] stabilize test --- src/test/groovy/graphql/ProfilerTest.groovy | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index f671898c0d..f0fe0e7326 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -268,6 +268,9 @@ class ProfilerTest extends Specification { def schema = TestUtil.schema(sdl, [ Query: [ foo: { DataFetchingEnvironment dfe -> + // blocking the engine for 1ms + // so that engineTotalRunningTime time is more than 1ms + Thread.sleep(1) return CompletableFuture.supplyAsync { Thread.sleep(500) "1" From ca618b4a12948558d8e1a43aaad450c71bfeefeb Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Sat, 19 Jul 2025 09:10:15 +1000 Subject: [PATCH 22/25] wip --- src/main/java/graphql/ProfilerResult.java | 42 --------------- src/test/groovy/graphql/ProfilerTest.groovy | 58 ++++++++++++++++++++- 2 files changed, 57 insertions(+), 43 deletions(-) diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index a5071f05e8..0a981403a5 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -171,7 +171,6 @@ void oldStrategyDispatchingAll(int level) { } - void addDispatchEvent(String dataLoaderName, @Nullable Integer level, int count, DispatchEventType type) { dispatchEvents.add(new DispatchEvent(dataLoaderName, level, count, type)); } @@ -264,47 +263,6 @@ public List getInstrumentationClasses() { return instrumentationClasses; } - public String fullSummary() { - return "ProfilerResult{" + - "executionId=" + executionId + - ", operation=" + operationType + ":" + operationName + - ", startTime=" + startTime + - ", endTime=" + endTime + - ", totalRunTime=" + (endTime - startTime) + "(" + (endTime - startTime) / 1_000_000 + "ms)" + - ", engineTotalRunningTime=" + engineTotalRunningTime + "(" + engineTotalRunningTime / 1_000_000 + "ms)" + - ", totalDataFetcherInvocations=" + totalDataFetcherInvocations + - ", totalPropertyDataFetcherInvocations=" + totalPropertyDataFetcherInvocations + - ", fieldsFetched=" + fieldsFetched + - ", dataFetcherInvocationCount=" + dataFetcherInvocationCount + - ", dataFetcherTypeMap=" + dataFetcherTypeMap + - ", dataFetcherResultType=" + dataFetcherResultType + - ", dataLoaderChainingEnabled=" + dataLoaderChainingEnabled + - ", dataLoaderLoadInvocations=" + dataLoaderLoadInvocations + - ", oldStrategyDispatchingAll=" + oldStrategyDispatchingAll + - ", dispatchEvents=" + printDispatchEvents() + - '}'; - } - - public String shortSummary() { - return "ProfilerResult{" + - "executionId=" + executionId + - ", operation=" + operationType + ":" + operationName + - ", startTime=" + startTime + - ", endTime=" + endTime + - ", totalRunTime=" + (endTime - startTime) + "(" + (endTime - startTime) / 1_000_000 + "ms)" + - ", engineTotalRunningTime=" + engineTotalRunningTime + "(" + engineTotalRunningTime / 1_000_000 + "ms)" + - ", totalDataFetcherInvocations=" + totalDataFetcherInvocations + - ", totalPropertyDataFetcherInvocations=" + totalPropertyDataFetcherInvocations + - ", fieldsFetchedCount=" + fieldsFetched.size() + - ", dataLoaderChainingEnabled=" + dataLoaderChainingEnabled + - ", dataLoaderLoadInvocations=" + dataLoaderLoadInvocations + - ", oldStrategyDispatchingAll=" + oldStrategyDispatchingAll + - ", dispatchEvents=" + printDispatchEvents() + - '}'; - - - } - public Map shortSummaryMap() { Map result = new LinkedHashMap<>(); result.put("executionId", Assert.assertNotNull(executionId)); diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index f0fe0e7326..ea886728bb 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -2,7 +2,9 @@ package graphql import graphql.execution.instrumentation.ChainedInstrumentation import graphql.execution.instrumentation.Instrumentation +import graphql.execution.instrumentation.InstrumentationState import graphql.execution.instrumentation.SimplePerformantInstrumentation +import graphql.execution.instrumentation.parameters.InstrumentationFieldFetchParameters import graphql.language.OperationDefinition import graphql.schema.DataFetcher import graphql.schema.DataFetchingEnvironment @@ -55,6 +57,60 @@ class ProfilerTest extends Specification { } + def "instrumented data fetcher"() { + given: + def sdl = ''' + type Query { + dog: Dog + } + type Dog { + name: String + age: Int + } + ''' + + + def dogDf = { DataFetchingEnvironment dfe -> return [name: "Luna", age: 5] } as DataFetcher + + Instrumentation instrumentation = new Instrumentation() { + @Override + DataFetcher instrumentDataFetcher(DataFetcher dataFetcher, InstrumentationFieldFetchParameters parameters, InstrumentationState state) { + if (parameters.getField().getName() == "name") { + // wrapping a PropertyDataFetcher + return { DataFetchingEnvironment dfe -> + def result = dataFetcher.get(dfe) + return result + } as DataFetcher + } + return dataFetcher + } + + } + def dfs = [Query: [ + dog: dogDf + ]] + def schema = TestUtil.schema(sdl, dfs) + def graphql = GraphQL.newGraphQL(schema).instrumentation(instrumentation).build(); + + ExecutionInput ei = ExecutionInput.newExecutionInput() + .query("{ dog {name age} }") + .profileExecution(true) + .build() + + when: + def result = graphql.execute(ei) + def profilerResult = ei.getGraphQLContext().get(ProfilerResult.PROFILER_CONTEXT_KEY) as ProfilerResult + + then: + result.getData() == [dog: [name: "Luna", age: 5]] + + then: + profilerResult.getTotalDataFetcherInvocations() == 3 + profilerResult.getTotalPropertyDataFetcherInvocations() == 1 + profilerResult.getTotalCustomDataFetcherInvocations() == 2 + } + + def "manual dataloader dispatch"() { given: def sdl = ''' @@ -210,8 +266,8 @@ class ProfilerTest extends Specification { then: profilerResult.getInstrumentationClasses() == ["graphql.execution.instrumentation.SimplePerformantInstrumentation", - "graphql.ProfilerTest\$1", "graphql.ProfilerTest\$2", + "graphql.ProfilerTest\$3", "graphql.execution.instrumentation.SimplePerformantInstrumentation"] } From 535eb8e5e6e814b1cd37ce79d9bfede8012f644a Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Sat, 19 Jul 2025 09:28:02 +1000 Subject: [PATCH 23/25] counting wrapped trivial data fetchers --- src/main/java/graphql/Profiler.java | 2 +- src/main/java/graphql/ProfilerImpl.java | 7 ++++-- src/main/java/graphql/ProfilerResult.java | 25 +++++++++++-------- .../execution/DataLoaderDispatchStrategy.java | 3 --- .../graphql/execution/ExecutionStrategy.java | 13 +++++----- src/test/groovy/graphql/ProfilerTest.groovy | 7 +++--- 6 files changed, 31 insertions(+), 26 deletions(-) diff --git a/src/main/java/graphql/Profiler.java b/src/main/java/graphql/Profiler.java index e43b59a0bd..3628e52cd0 100644 --- a/src/main/java/graphql/Profiler.java +++ b/src/main/java/graphql/Profiler.java @@ -26,7 +26,7 @@ default void dataLoaderUsed(String dataLoaderName) { } - default void fieldFetched(Object fetchedObject, DataFetcher dataFetcher, ResultPath path) { + default void fieldFetched(Object fetchedObject, DataFetcher originalDataFetcher, DataFetcher dataFetcher, ResultPath path) { } diff --git a/src/main/java/graphql/ProfilerImpl.java b/src/main/java/graphql/ProfilerImpl.java index 1a062c8b26..7a689c9d69 100644 --- a/src/main/java/graphql/ProfilerImpl.java +++ b/src/main/java/graphql/ProfilerImpl.java @@ -56,14 +56,17 @@ private void collectInstrumentationClasses(List result, Instrumentation } } + @Override - public void fieldFetched(Object fetchedObject, DataFetcher dataFetcher, ResultPath path) { + public void fieldFetched(Object fetchedObject, DataFetcher originalDataFetcher, DataFetcher dataFetcher, ResultPath path) { String key = "/" + String.join("/", path.getKeysOnly()); profilerResult.addFieldFetched(key); profilerResult.incrementDataFetcherInvocationCount(key); ProfilerResult.DataFetcherType dataFetcherType; if (dataFetcher instanceof PropertyDataFetcher || dataFetcher instanceof SingletonPropertyDataFetcher) { - dataFetcherType = ProfilerResult.DataFetcherType.PROPERTY_DATA_FETCHER; + dataFetcherType = ProfilerResult.DataFetcherType.TRIVIAL_DATA_FETCHER; + } else if (originalDataFetcher instanceof PropertyDataFetcher || originalDataFetcher instanceof SingletonPropertyDataFetcher) { + dataFetcherType = ProfilerResult.DataFetcherType.WRAPPED_TRIVIAL_DATA_FETCHER; } else { dataFetcherType = ProfilerResult.DataFetcherType.CUSTOM; // we only record the type of the result if it is not a PropertyDataFetcher diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index 0a981403a5..57e85917e7 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -28,7 +28,8 @@ public class ProfilerResult { private long endTime; private long engineTotalRunningTime; private final AtomicInteger totalDataFetcherInvocations = new AtomicInteger(); - private final AtomicInteger totalPropertyDataFetcherInvocations = new AtomicInteger(); + private final AtomicInteger totalTrivialDataFetcherInvocations = new AtomicInteger(); + private final AtomicInteger totalWrappedTrivialDataFetcherInvocations = new AtomicInteger(); // this is the count of how many times a data loader was invoked per data loader name private final Map dataLoaderLoadInvocations = new ConcurrentHashMap<>(); @@ -108,7 +109,8 @@ public String toString() { } public enum DataFetcherType { - PROPERTY_DATA_FETCHER, + WRAPPED_TRIVIAL_DATA_FETCHER, + TRIVIAL_DATA_FETCHER, CUSTOM } @@ -130,8 +132,10 @@ void setDataLoaderChainingEnabled(boolean dataLoaderChainingEnabled) { void setDataFetcherType(String key, DataFetcherType dataFetcherType) { dataFetcherTypeMap.putIfAbsent(key, dataFetcherType); totalDataFetcherInvocations.incrementAndGet(); - if (dataFetcherType == DataFetcherType.PROPERTY_DATA_FETCHER) { - totalPropertyDataFetcherInvocations.incrementAndGet(); + if (dataFetcherType == DataFetcherType.TRIVIAL_DATA_FETCHER) { + totalTrivialDataFetcherInvocations.incrementAndGet(); + } else if (dataFetcherType == DataFetcherType.WRAPPED_TRIVIAL_DATA_FETCHER) { + totalWrappedTrivialDataFetcherInvocations.incrementAndGet(); } } @@ -199,10 +203,10 @@ public Set getCustomDataFetcherFields() { return result; } - public Set getPropertyDataFetcherFields() { + public Set getTrivialDataFetcherFields() { Set result = new LinkedHashSet<>(fieldsFetched); for (String field : fieldsFetched) { - if (dataFetcherTypeMap.get(field) == DataFetcherType.PROPERTY_DATA_FETCHER) { + if (dataFetcherTypeMap.get(field) == DataFetcherType.TRIVIAL_DATA_FETCHER) { result.add(field); } } @@ -214,12 +218,12 @@ public int getTotalDataFetcherInvocations() { return totalDataFetcherInvocations.get(); } - public int getTotalPropertyDataFetcherInvocations() { - return totalPropertyDataFetcherInvocations.get(); + public int getTotalTrivialDataFetcherInvocations() { + return totalTrivialDataFetcherInvocations.get(); } public int getTotalCustomDataFetcherInvocations() { - return totalDataFetcherInvocations.get() - totalPropertyDataFetcherInvocations.get(); + return totalDataFetcherInvocations.get() - totalTrivialDataFetcherInvocations.get() - totalWrappedTrivialDataFetcherInvocations.get(); } public long getStartTime() { @@ -272,7 +276,8 @@ public Map shortSummaryMap() { result.put("totalRunTime", (endTime - startTime) + "(" + (endTime - startTime) / 1_000_000 + "ms)"); result.put("engineTotalRunningTime", engineTotalRunningTime + "(" + engineTotalRunningTime / 1_000_000 + "ms)"); result.put("totalDataFetcherInvocations", totalDataFetcherInvocations); - result.put("totalPropertyDataFetcherInvocations", totalPropertyDataFetcherInvocations); + result.put("totalTrivialDataFetcherInvocations", totalTrivialDataFetcherInvocations); + result.put("totalWrappedTrivialDataFetcherInvocations", totalWrappedTrivialDataFetcherInvocations); result.put("fieldsFetchedCount", fieldsFetched.size()); result.put("dataLoaderChainingEnabled", dataLoaderChainingEnabled); result.put("dataLoaderLoadInvocations", dataLoaderLoadInvocations); diff --git a/src/main/java/graphql/execution/DataLoaderDispatchStrategy.java b/src/main/java/graphql/execution/DataLoaderDispatchStrategy.java index 13d918bdd9..b3f837cd5c 100644 --- a/src/main/java/graphql/execution/DataLoaderDispatchStrategy.java +++ b/src/main/java/graphql/execution/DataLoaderDispatchStrategy.java @@ -57,9 +57,6 @@ default void fieldFetched(ExecutionContext executionContext, } - default DataFetcher modifyDataFetcher(DataFetcher dataFetcher) { - return dataFetcher; - } default void newSubscriptionExecution(FieldValueInfo fieldValueInfo, AlternativeCallContext alternativeCallContext) { diff --git a/src/main/java/graphql/execution/ExecutionStrategy.java b/src/main/java/graphql/execution/ExecutionStrategy.java index fbc2f40b8a..7bf0a3d2dd 100644 --- a/src/main/java/graphql/execution/ExecutionStrategy.java +++ b/src/main/java/graphql/execution/ExecutionStrategy.java @@ -447,18 +447,17 @@ private Object fetchField(GraphQLFieldDefinition fieldDef, ExecutionContext exec }); GraphQLCodeRegistry codeRegistry = executionContext.getGraphQLSchema().getCodeRegistry(); - DataFetcher dataFetcher = codeRegistry.getDataFetcher(parentType, fieldDef); + DataFetcher originalDataFetcher = codeRegistry.getDataFetcher(parentType, fieldDef); Instrumentation instrumentation = executionContext.getInstrumentation(); - InstrumentationFieldFetchParameters instrumentationFieldFetchParams = new InstrumentationFieldFetchParameters(executionContext, dataFetchingEnvironment, parameters, dataFetcher instanceof TrivialDataFetcher); + InstrumentationFieldFetchParameters instrumentationFieldFetchParams = new InstrumentationFieldFetchParameters(executionContext, dataFetchingEnvironment, parameters, originalDataFetcher instanceof TrivialDataFetcher); FieldFetchingInstrumentationContext fetchCtx = FieldFetchingInstrumentationContext.nonNullCtx(instrumentation.beginFieldFetching(instrumentationFieldFetchParams, executionContext.getInstrumentationState()) ); - dataFetcher = instrumentation.instrumentDataFetcher(dataFetcher, instrumentationFieldFetchParams, executionContext.getInstrumentationState()); - dataFetcher = executionContext.getDataLoaderDispatcherStrategy().modifyDataFetcher(dataFetcher); - Object fetchedObject = invokeDataFetcher(executionContext, parameters, fieldDef, dataFetchingEnvironment, dataFetcher); + DataFetcher dataFetcher = instrumentation.instrumentDataFetcher(originalDataFetcher, instrumentationFieldFetchParams, executionContext.getInstrumentationState()); + Object fetchedObject = invokeDataFetcher(executionContext, parameters, fieldDef, dataFetchingEnvironment, originalDataFetcher, dataFetcher); executionContext.getDataLoaderDispatcherStrategy().fieldFetched(executionContext, parameters, dataFetcher, fetchedObject, dataFetchingEnvironment); fetchCtx.onDispatched(); fetchCtx.onFetchedValue(fetchedObject); @@ -497,7 +496,7 @@ private Object fetchField(GraphQLFieldDefinition fieldDef, ExecutionContext exec * ExecutionContext is not used in the method, but the java agent uses it, so it needs to be present */ @SuppressWarnings("unused") - private Object invokeDataFetcher(ExecutionContext executionContext, ExecutionStrategyParameters parameters, GraphQLFieldDefinition fieldDef, Supplier dataFetchingEnvironment, DataFetcher dataFetcher) { + private Object invokeDataFetcher(ExecutionContext executionContext, ExecutionStrategyParameters parameters, GraphQLFieldDefinition fieldDef, Supplier dataFetchingEnvironment, DataFetcher originalDataFetcher, DataFetcher dataFetcher) { Object fetchedValue; try { Object fetchedValueRaw; @@ -506,7 +505,7 @@ private Object invokeDataFetcher(ExecutionContext executionContext, ExecutionStr } else { fetchedValueRaw = dataFetcher.get(dataFetchingEnvironment.get()); } - executionContext.getProfiler().fieldFetched(fetchedValueRaw, dataFetcher, parameters.getPath()); + executionContext.getProfiler().fieldFetched(fetchedValueRaw, originalDataFetcher, dataFetcher, parameters.getPath()); fetchedValue = Async.toCompletableFutureOrMaterializedObject(fetchedValueRaw); } catch (Exception e) { fetchedValue = Async.exceptionallyCompletedFuture(e); diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index ea886728bb..1d9b35b4d5 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -106,8 +106,9 @@ class ProfilerTest extends Specification { then: profilerResult.getTotalDataFetcherInvocations() == 3 - profilerResult.getTotalPropertyDataFetcherInvocations() == 1 - profilerResult.getTotalCustomDataFetcherInvocations() == 2 + profilerResult.getTotalTrivialDataFetcherInvocations() == 1 + profilerResult.getTotalTrivialDataFetcherInvocations() == 1 + profilerResult.getTotalCustomDataFetcherInvocations() == 1 } @@ -308,7 +309,7 @@ class ProfilerTest extends Specification { profilerResult.getFieldsFetched() == ["/foo", "/foo/bar", "/foo/id"] as Set profilerResult.getTotalDataFetcherInvocations() == 7 profilerResult.getTotalCustomDataFetcherInvocations() == 4 - profilerResult.getTotalPropertyDataFetcherInvocations() == 3 + profilerResult.getTotalTrivialDataFetcherInvocations() == 3 } def "records timing"() { From a04f5cbf95b051c6d0084348dc6dba31485aecd6 Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Sat, 19 Jul 2025 11:02:49 +1000 Subject: [PATCH 24/25] introspection fields --- src/main/java/graphql/Profiler.java | 4 +- src/main/java/graphql/ProfilerImpl.java | 13 +++- src/main/java/graphql/ProfilerResult.java | 30 +++++++++ .../graphql/execution/ExecutionStrategy.java | 2 +- src/test/groovy/graphql/ProfilerTest.groovy | 63 +++++++++++++++++++ 5 files changed, 109 insertions(+), 3 deletions(-) diff --git a/src/main/java/graphql/Profiler.java b/src/main/java/graphql/Profiler.java index 3628e52cd0..6ac692a2fa 100644 --- a/src/main/java/graphql/Profiler.java +++ b/src/main/java/graphql/Profiler.java @@ -5,6 +5,8 @@ import graphql.execution.instrumentation.Instrumentation; import graphql.language.OperationDefinition; import graphql.schema.DataFetcher; +import graphql.schema.GraphQLFieldDefinition; +import graphql.schema.GraphQLOutputType; import org.jspecify.annotations.NullMarked; import org.jspecify.annotations.Nullable; @@ -26,7 +28,7 @@ default void dataLoaderUsed(String dataLoaderName) { } - default void fieldFetched(Object fetchedObject, DataFetcher originalDataFetcher, DataFetcher dataFetcher, ResultPath path) { + default void fieldFetched(Object fetchedObject, DataFetcher originalDataFetcher, DataFetcher dataFetcher, ResultPath path, GraphQLFieldDefinition fieldDef, GraphQLOutputType parentType) { } diff --git a/src/main/java/graphql/ProfilerImpl.java b/src/main/java/graphql/ProfilerImpl.java index 7a689c9d69..5c2e284dd5 100644 --- a/src/main/java/graphql/ProfilerImpl.java +++ b/src/main/java/graphql/ProfilerImpl.java @@ -6,8 +6,12 @@ import graphql.execution.instrumentation.ChainedInstrumentation; import graphql.execution.instrumentation.Instrumentation; import graphql.execution.instrumentation.dataloader.DataLoaderDispatchingContextKeys; +import graphql.introspection.Introspection; import graphql.language.OperationDefinition; import graphql.schema.DataFetcher; +import graphql.schema.GraphQLFieldDefinition; +import graphql.schema.GraphQLOutputType; +import graphql.schema.GraphQLTypeUtil; import graphql.schema.PropertyDataFetcher; import graphql.schema.SingletonPropertyDataFetcher; import org.jspecify.annotations.NullMarked; @@ -58,8 +62,15 @@ private void collectInstrumentationClasses(List result, Instrumentation @Override - public void fieldFetched(Object fetchedObject, DataFetcher originalDataFetcher, DataFetcher dataFetcher, ResultPath path) { + public void fieldFetched(Object fetchedObject, DataFetcher originalDataFetcher, DataFetcher dataFetcher, ResultPath path, GraphQLFieldDefinition fieldDef, GraphQLOutputType parentType) { String key = "/" + String.join("/", path.getKeysOnly()); + if (Introspection.isIntrospectionTypes(GraphQLTypeUtil.unwrapAll(fieldDef.getType())) + || Introspection.isIntrospectionTypes(GraphQLTypeUtil.unwrapAll(parentType)) + || fieldDef.getName().equals(Introspection.SchemaMetaFieldDef.getName()) + || fieldDef.getName().equals(Introspection.TypeMetaFieldDef.getName()) + || fieldDef.getName().equals(Introspection.TypeNameMetaFieldDef.getName())) { + return; + } profilerResult.addFieldFetched(key); profilerResult.incrementDataFetcherInvocationCount(key); ProfilerResult.DataFetcherType dataFetcherType; diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index 57e85917e7..dc3a84f614 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -267,6 +267,7 @@ public List getInstrumentationClasses() { return instrumentationClasses; } + public Map shortSummaryMap() { Map result = new LinkedHashMap<>(); result.put("executionId", Assert.assertNotNull(executionId)); @@ -276,6 +277,7 @@ public Map shortSummaryMap() { result.put("totalRunTime", (endTime - startTime) + "(" + (endTime - startTime) / 1_000_000 + "ms)"); result.put("engineTotalRunningTime", engineTotalRunningTime + "(" + engineTotalRunningTime / 1_000_000 + "ms)"); result.put("totalDataFetcherInvocations", totalDataFetcherInvocations); + result.put("totalCustomDataFetcherInvocations", getTotalCustomDataFetcherInvocations()); result.put("totalTrivialDataFetcherInvocations", totalTrivialDataFetcherInvocations); result.put("totalWrappedTrivialDataFetcherInvocations", totalWrappedTrivialDataFetcherInvocations); result.put("fieldsFetchedCount", fieldsFetched.size()); @@ -284,6 +286,34 @@ public Map shortSummaryMap() { result.put("oldStrategyDispatchingAll", oldStrategyDispatchingAll); result.put("dispatchEvents", getDispatchEventsAsMap()); result.put("instrumentationClasses", instrumentationClasses); + int completedCount = 0; + int notCompletedCount = 0; + int materializedCount = 0; + // we want to minimize the overall size because it is intended to be logged + // and logging can be expensive and is limited in size very often + Map resultTypes = new LinkedHashMap<>(); + for (String field : dataFetcherResultType.keySet()) { + DataFetcherResultType dataFetcherResultType1 = dataFetcherResultType.get(field); + String shortType = null; + if (dataFetcherResultType1 == DataFetcherResultType.COMPLETABLE_FUTURE_COMPLETED) { + completedCount++; + shortType = "C"; + } else if (dataFetcherResultType1 == DataFetcherResultType.COMPLETABLE_FUTURE_NOT_COMPLETED) { + notCompletedCount++; + shortType = "N"; + } else if (dataFetcherResultType1 == DataFetcherResultType.MATERIALIZED) { + materializedCount++; + shortType = "M"; + } else { + Assert.assertShouldNeverHappen(); + } + resultTypes.put(field, Assert.assertNotNull(shortType)); + } + result.put("dataFetcherResultTypesCount", Map.of( + DataFetcherResultType.COMPLETABLE_FUTURE_COMPLETED, completedCount, + DataFetcherResultType.COMPLETABLE_FUTURE_NOT_COMPLETED, notCompletedCount, + DataFetcherResultType.MATERIALIZED, materializedCount)); + result.put("dataFetcherResultType", resultTypes); return result; } diff --git a/src/main/java/graphql/execution/ExecutionStrategy.java b/src/main/java/graphql/execution/ExecutionStrategy.java index 7bf0a3d2dd..a16f0f80f1 100644 --- a/src/main/java/graphql/execution/ExecutionStrategy.java +++ b/src/main/java/graphql/execution/ExecutionStrategy.java @@ -505,7 +505,7 @@ private Object invokeDataFetcher(ExecutionContext executionContext, ExecutionStr } else { fetchedValueRaw = dataFetcher.get(dataFetchingEnvironment.get()); } - executionContext.getProfiler().fieldFetched(fetchedValueRaw, originalDataFetcher, dataFetcher, parameters.getPath()); + executionContext.getProfiler().fieldFetched(fetchedValueRaw, originalDataFetcher, dataFetcher, parameters.getPath(), fieldDef, parameters.getExecutionStepInfo().getType()); fetchedValue = Async.toCompletableFutureOrMaterializedObject(fetchedValueRaw); } catch (Exception e) { fetchedValue = Async.exceptionallyCompletedFuture(e); diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index 1d9b35b4d5..25f3fd5ad0 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -22,6 +22,7 @@ import java.util.concurrent.atomic.AtomicInteger import static graphql.ExecutionInput.newExecutionInput import static graphql.ProfilerResult.DataFetcherResultType.COMPLETABLE_FUTURE_COMPLETED import static graphql.ProfilerResult.DataFetcherResultType.COMPLETABLE_FUTURE_NOT_COMPLETED +import static graphql.ProfilerResult.DataFetcherResultType.MATERIALIZED import static graphql.execution.instrumentation.dataloader.DataLoaderDispatchingContextKeys.setEnableDataLoaderChaining import static java.util.concurrent.CompletableFuture.supplyAsync @@ -57,6 +58,67 @@ class ProfilerTest extends Specification { } + def "introspection fields are ignored"() { + given: + def sdl = ''' + type Query { + hello: String + } + ''' + def schema = TestUtil.schema(sdl, [Query: [ + hello: { DataFetchingEnvironment dfe -> return "world" } as DataFetcher + ]]) + def graphql = GraphQL.newGraphQL(schema).build(); + + ExecutionInput ei = ExecutionInput.newExecutionInput() + .query("{ hello __typename alias:__typename __schema {types{name}} __type(name: \"Query\") {name} }") + .profileExecution(true) + .build() + + when: + def result = graphql.execute(ei) + def profilerResult = ei.getGraphQLContext().get(ProfilerResult.PROFILER_CONTEXT_KEY) as ProfilerResult + + then: + result.getData()["hello"] == "world" + + then: + profilerResult.getFieldsFetched() == ["/hello",] as Set + profilerResult.getTotalDataFetcherInvocations() == 1 + + } + + def "pure introspection "() { + given: + def sdl = ''' + type Query { + hello: String + } + ''' + def schema = TestUtil.schema(sdl, [Query: [ + hello: { DataFetchingEnvironment dfe -> return "world" } as DataFetcher + ]]) + def graphql = GraphQL.newGraphQL(schema).build(); + + ExecutionInput ei = ExecutionInput.newExecutionInput() + .query("{ __schema {types{name}} __type(name: \"Query\") {name} }") + .profileExecution(true) + .build() + + when: + def result = graphql.execute(ei) + def profilerResult = ei.getGraphQLContext().get(ProfilerResult.PROFILER_CONTEXT_KEY) as ProfilerResult + + then: + result.getData()["__schema"] != null + + then: + profilerResult.getFieldsFetched() == [] as Set + profilerResult.getTotalDataFetcherInvocations() == 0 + + } + + def "instrumented data fetcher"() { given: def sdl = ''' @@ -109,6 +171,7 @@ class ProfilerTest extends Specification { profilerResult.getTotalTrivialDataFetcherInvocations() == 1 profilerResult.getTotalTrivialDataFetcherInvocations() == 1 profilerResult.getTotalCustomDataFetcherInvocations() == 1 + profilerResult.getDataFetcherResultType() == ["/dog": MATERIALIZED] } From 572090e03963be0625b0202f31dee0238881b89c Mon Sep 17 00:00:00 2001 From: Andreas Marek Date: Sat, 19 Jul 2025 11:32:44 +1000 Subject: [PATCH 25/25] data fetcher type statistics --- src/main/java/graphql/ProfilerResult.java | 32 ++++++++++----------- src/test/groovy/graphql/ProfilerTest.groovy | 24 +++++++++++++--- 2 files changed, 35 insertions(+), 21 deletions(-) diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index dc3a84f614..a10e55c8a1 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -287,33 +287,31 @@ public Map shortSummaryMap() { result.put("dispatchEvents", getDispatchEventsAsMap()); result.put("instrumentationClasses", instrumentationClasses); int completedCount = 0; + int completedInvokeCount = 0; int notCompletedCount = 0; + int notCompletedInvokeCount = 0; int materializedCount = 0; - // we want to minimize the overall size because it is intended to be logged - // and logging can be expensive and is limited in size very often - Map resultTypes = new LinkedHashMap<>(); + int materializedInvokeCount = 0; for (String field : dataFetcherResultType.keySet()) { - DataFetcherResultType dataFetcherResultType1 = dataFetcherResultType.get(field); - String shortType = null; - if (dataFetcherResultType1 == DataFetcherResultType.COMPLETABLE_FUTURE_COMPLETED) { + DataFetcherResultType dFRT = dataFetcherResultType.get(field); + if (dFRT == DataFetcherResultType.COMPLETABLE_FUTURE_COMPLETED) { + completedInvokeCount += Assert.assertNotNull(dataFetcherInvocationCount.get(field)); completedCount++; - shortType = "C"; - } else if (dataFetcherResultType1 == DataFetcherResultType.COMPLETABLE_FUTURE_NOT_COMPLETED) { + } else if (dFRT == DataFetcherResultType.COMPLETABLE_FUTURE_NOT_COMPLETED) { + notCompletedInvokeCount += Assert.assertNotNull(dataFetcherInvocationCount.get(field)); notCompletedCount++; - shortType = "N"; - } else if (dataFetcherResultType1 == DataFetcherResultType.MATERIALIZED) { + } else if (dFRT == DataFetcherResultType.MATERIALIZED) { + materializedInvokeCount += Assert.assertNotNull(dataFetcherInvocationCount.get(field)); materializedCount++; - shortType = "M"; } else { Assert.assertShouldNeverHappen(); } - resultTypes.put(field, Assert.assertNotNull(shortType)); } - result.put("dataFetcherResultTypesCount", Map.of( - DataFetcherResultType.COMPLETABLE_FUTURE_COMPLETED, completedCount, - DataFetcherResultType.COMPLETABLE_FUTURE_NOT_COMPLETED, notCompletedCount, - DataFetcherResultType.MATERIALIZED, materializedCount)); - result.put("dataFetcherResultType", resultTypes); + result.put("dataFetcherResultTypes", Map.of( + DataFetcherResultType.COMPLETABLE_FUTURE_COMPLETED.name(), "(count:" + completedCount + ", invocations:" + completedInvokeCount + ")", + DataFetcherResultType.COMPLETABLE_FUTURE_NOT_COMPLETED.name(), "(count:" + notCompletedCount + ", invocations:" + notCompletedInvokeCount + ")", + DataFetcherResultType.MATERIALIZED.name(), "(count:" + materializedCount + ", invocations:" + materializedInvokeCount + ")" + )); return result; } diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index 25f3fd5ad0..25b58a6068 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -435,6 +435,7 @@ class ProfilerTest extends Specification { type Foo { id: String name: String + text: String } ''' def schema = TestUtil.schema(sdl, [ @@ -442,18 +443,22 @@ class ProfilerTest extends Specification { foo: { DataFetchingEnvironment dfe -> return CompletableFuture.supplyAsync { Thread.sleep(100) - return [[id: "1", name: "foo"]] + return [[id: "1", name: "foo1"], [id: "2", name: "foo2"]] } } as DataFetcher], Foo : [ name: { DataFetchingEnvironment dfe -> return CompletableFuture.completedFuture(dfe.source.name) + } as DataFetcher, + text: { DataFetchingEnvironment dfe -> + return "text" } as DataFetcher + ]]) def graphql = GraphQL.newGraphQL(schema).build(); ExecutionInput ei = ExecutionInput.newExecutionInput() - .query("{ foo { id name } }") + .query("{ foo { id name text } foo2: foo { id name text} }") .profileExecution(true) .build() @@ -462,8 +467,19 @@ class ProfilerTest extends Specification { def profilerResult = ei.getGraphQLContext().get(ProfilerResult.PROFILER_CONTEXT_KEY) as ProfilerResult then: - result.getData() == [foo: [[id: "1", name: "foo"]]] - profilerResult.getDataFetcherResultType() == ["/foo/name": COMPLETABLE_FUTURE_COMPLETED, "/foo": COMPLETABLE_FUTURE_NOT_COMPLETED] + result.getData() == [foo: [[id: "1", name: "foo1", text: "text"], [id: "2", name: "foo2", text: "text"]], foo2: [[id: "1", name: "foo1", text: "text"], [id: "2", name: "foo2", text: "text"]]] + then: + profilerResult.getTotalDataFetcherInvocations() == 14 + profilerResult.getTotalCustomDataFetcherInvocations() == 10 + profilerResult.getDataFetcherResultType() == ["/foo/name" : COMPLETABLE_FUTURE_COMPLETED, + "/foo/text" : MATERIALIZED, + "/foo2/name": COMPLETABLE_FUTURE_COMPLETED, + "/foo2/text": MATERIALIZED, + "/foo2" : COMPLETABLE_FUTURE_NOT_COMPLETED, + "/foo" : COMPLETABLE_FUTURE_NOT_COMPLETED] + profilerResult.shortSummaryMap().get("dataFetcherResultTypes") == ["COMPLETABLE_FUTURE_COMPLETED" : "(count:2, invocations:4)", + "COMPLETABLE_FUTURE_NOT_COMPLETED": "(count:2, invocations:2)", + "MATERIALIZED" : "(count:2, invocations:4)"] }