From b69dd6b86e8bef01796e016770c431b70880a16e Mon Sep 17 00:00:00 2001 From: dondonz <13839920+dondonz@users.noreply.github.com> Date: Thu, 31 Jul 2025 08:11:50 +1000 Subject: [PATCH 1/7] Cast execution ID to string to make this easier to log --- src/main/java/graphql/ProfilerResult.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index bf5159dce9..326fcbf62f 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -273,7 +273,7 @@ public List getInstrumentationClasses() { public Map shortSummaryMap() { Map result = new LinkedHashMap<>(); - result.put("executionId", Assert.assertNotNull(executionId)); + result.put("executionId", Assert.assertNotNull(executionId).toString()); result.put("operation", operationType + ":" + operationName); result.put("startTime", startTime); result.put("endTime", endTime); From 5de46cd41d00586ba94a7ca4204f3c6da686a0be Mon Sep 17 00:00:00 2001 From: dondonz <13839920+dondonz@users.noreply.github.com> Date: Thu, 31 Jul 2025 09:53:31 +1000 Subject: [PATCH 2/7] Add test to for ExecutionId cast to string in profiler output --- src/test/groovy/graphql/ProfilerTest.groovy | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index 1498417c3e..d7c0f27881 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -1,5 +1,6 @@ package graphql +import graphql.execution.ExecutionId import graphql.execution.instrumentation.ChainedInstrumentation import graphql.execution.instrumentation.Instrumentation import graphql.execution.instrumentation.InstrumentationState @@ -457,9 +458,11 @@ class ProfilerTest extends Specification { ]]) def graphql = GraphQL.newGraphQL(schema).build(); + ExecutionId id = ExecutionId.from("myExecutionId") ExecutionInput ei = ExecutionInput.newExecutionInput() .query("{ foo { id name text } foo2: foo { id name text} }") .profileExecution(true) + .executionId(id) .build() when: @@ -480,8 +483,7 @@ class ProfilerTest extends Specification { profilerResult.shortSummaryMap().get("dataFetcherResultTypes") == ["COMPLETABLE_FUTURE_COMPLETED" : "(count:2, invocations:4)", "COMPLETABLE_FUTURE_NOT_COMPLETED": "(count:2, invocations:2)", "MATERIALIZED" : "(count:2, invocations:4)"] - - + profilerResult.shortSummaryMap().get("executionId") == "myExecutionId" } def "operation details"() { From eb90338eaecf93c6d055d0a53be77f3345cd7c05 Mon Sep 17 00:00:00 2001 From: dondonz <13839920+dondonz@users.noreply.github.com> Date: Thu, 31 Jul 2025 16:18:46 +1000 Subject: [PATCH 3/7] More formatting updates and remove Map.of which is not deterministic in order --- src/main/java/graphql/ProfilerResult.java | 24 ++++++++++++++++------- 1 file changed, 17 insertions(+), 7 deletions(-) diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index 326fcbf62f..8fad8acbed 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -277,8 +277,8 @@ public Map shortSummaryMap() { 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("totalRunTimeNs", endTime - startTime); + result.put("engineTotalRunningTimeNs", engineTotalRunningTime); result.put("totalDataFetcherInvocations", totalDataFetcherInvocations); result.put("totalCustomDataFetcherInvocations", getTotalCustomDataFetcherInvocations()); result.put("totalTrivialDataFetcherInvocations", totalTrivialDataFetcherInvocations); @@ -310,11 +310,21 @@ public Map shortSummaryMap() { Assert.assertShouldNeverHappen(); } } - 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 + ")" - )); + LinkedHashMap dFRTinfo = new LinkedHashMap<>(3); + LinkedHashMap completableFutureCompleted = new LinkedHashMap<>(2); + completableFutureCompleted.put("count", completedCount); + completableFutureCompleted.put("invocations", completedInvokeCount); + LinkedHashMap completableFutureNotCompleted = new LinkedHashMap<>(2); + completableFutureNotCompleted.put("count", notCompletedCount); + completableFutureNotCompleted.put("invocations", notCompletedInvokeCount); + LinkedHashMap materialized = new LinkedHashMap<>(2); + materialized.put("count", materializedCount); + materialized.put("invocations", materializedInvokeCount); + + dFRTinfo.put(DataFetcherResultType.COMPLETABLE_FUTURE_COMPLETED.name(), completableFutureCompleted); + dFRTinfo.put(DataFetcherResultType.COMPLETABLE_FUTURE_NOT_COMPLETED.name(), completableFutureNotCompleted); + dFRTinfo.put(DataFetcherResultType.MATERIALIZED.name(), materialized); + result.put("dataFetcherResultTypes", dFRTinfo); return result; } From fde7f50db60c2c5c5c3153b57cba88fd8a075e27 Mon Sep 17 00:00:00 2001 From: dondonz <13839920+dondonz@users.noreply.github.com> Date: Thu, 31 Jul 2025 17:22:03 +1000 Subject: [PATCH 4/7] Use a helper method instead --- src/main/java/graphql/ProfilerResult.java | 22 +++++++++------------- 1 file changed, 9 insertions(+), 13 deletions(-) diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index 8fad8acbed..9042fe7305 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -311,23 +311,19 @@ public Map shortSummaryMap() { } } LinkedHashMap dFRTinfo = new LinkedHashMap<>(3); - LinkedHashMap completableFutureCompleted = new LinkedHashMap<>(2); - completableFutureCompleted.put("count", completedCount); - completableFutureCompleted.put("invocations", completedInvokeCount); - LinkedHashMap completableFutureNotCompleted = new LinkedHashMap<>(2); - completableFutureNotCompleted.put("count", notCompletedCount); - completableFutureNotCompleted.put("invocations", notCompletedInvokeCount); - LinkedHashMap materialized = new LinkedHashMap<>(2); - materialized.put("count", materializedCount); - materialized.put("invocations", materializedInvokeCount); - - dFRTinfo.put(DataFetcherResultType.COMPLETABLE_FUTURE_COMPLETED.name(), completableFutureCompleted); - dFRTinfo.put(DataFetcherResultType.COMPLETABLE_FUTURE_NOT_COMPLETED.name(), completableFutureNotCompleted); - dFRTinfo.put(DataFetcherResultType.MATERIALIZED.name(), materialized); + dFRTinfo.put(DataFetcherResultType.COMPLETABLE_FUTURE_COMPLETED.name(), createCountMap(completedCount, completedInvokeCount)); + dFRTinfo.put(DataFetcherResultType.COMPLETABLE_FUTURE_NOT_COMPLETED.name(), createCountMap(notCompletedCount, notCompletedInvokeCount)); + dFRTinfo.put(DataFetcherResultType.MATERIALIZED.name(), createCountMap(materializedCount, materializedInvokeCount)); result.put("dataFetcherResultTypes", dFRTinfo); return result; } + private LinkedHashMap createCountMap(int count, int invocations) { + LinkedHashMap map = new LinkedHashMap<>(2); + map.put("count", count); + map.put("invocations", invocations); + return map; + } public List> getDispatchEventsAsMap() { List> result = new ArrayList<>(); From 1c76bec6263cfd159d97eb02e38d8ae8825ff26a Mon Sep 17 00:00:00 2001 From: dondonz <13839920+dondonz@users.noreply.github.com> Date: Thu, 31 Jul 2025 17:32:35 +1000 Subject: [PATCH 5/7] Update test and IDE warnings --- src/test/groovy/graphql/ProfilerTest.groovy | 68 ++++++++++----------- 1 file changed, 34 insertions(+), 34 deletions(-) diff --git a/src/test/groovy/graphql/ProfilerTest.groovy b/src/test/groovy/graphql/ProfilerTest.groovy index d7c0f27881..96cc2098c4 100644 --- a/src/test/groovy/graphql/ProfilerTest.groovy +++ b/src/test/groovy/graphql/ProfilerTest.groovy @@ -40,9 +40,9 @@ class ProfilerTest extends Specification { def schema = TestUtil.schema(sdl, [Query: [ hello: { DataFetchingEnvironment dfe -> return "world" } as DataFetcher ]]) - def graphql = GraphQL.newGraphQL(schema).build(); + def graphql = GraphQL.newGraphQL(schema).build() - ExecutionInput ei = ExecutionInput.newExecutionInput() + ExecutionInput ei = newExecutionInput() .query("{ hello }") .profileExecution(true) .build() @@ -69,9 +69,9 @@ class ProfilerTest extends Specification { def schema = TestUtil.schema(sdl, [Query: [ hello: { DataFetchingEnvironment dfe -> return "world" } as DataFetcher ]]) - def graphql = GraphQL.newGraphQL(schema).build(); + def graphql = GraphQL.newGraphQL(schema).build() - ExecutionInput ei = ExecutionInput.newExecutionInput() + ExecutionInput ei = newExecutionInput() .query("{ hello __typename alias:__typename __schema {types{name}} __type(name: \"Query\") {name} }") .profileExecution(true) .build() @@ -99,9 +99,9 @@ class ProfilerTest extends Specification { def schema = TestUtil.schema(sdl, [Query: [ hello: { DataFetchingEnvironment dfe -> return "world" } as DataFetcher ]]) - def graphql = GraphQL.newGraphQL(schema).build(); + def graphql = GraphQL.newGraphQL(schema).build() - ExecutionInput ei = ExecutionInput.newExecutionInput() + ExecutionInput ei = newExecutionInput() .query("{ __schema {types{name}} __type(name: \"Query\") {name} }") .profileExecution(true) .build() @@ -153,9 +153,9 @@ class ProfilerTest extends Specification { dog: dogDf ]] def schema = TestUtil.schema(sdl, dfs) - def graphql = GraphQL.newGraphQL(schema).instrumentation(instrumentation).build(); + def graphql = GraphQL.newGraphQL(schema).instrumentation(instrumentation).build() - ExecutionInput ei = ExecutionInput.newExecutionInput() + ExecutionInput ei = newExecutionInput() .query("{ dog {name age} }") .profileExecution(true) .build() @@ -194,10 +194,10 @@ class ProfilerTest extends Specification { } } - DataLoader nameDataLoader = DataLoaderFactory.newDataLoader(batchLoader); + DataLoader nameDataLoader = DataLoaderFactory.newDataLoader(batchLoader) - DataLoaderRegistry dataLoaderRegistry = new DataLoaderRegistry(); - dataLoaderRegistry.register("name", nameDataLoader); + DataLoaderRegistry dataLoaderRegistry = new DataLoaderRegistry() + dataLoaderRegistry.register("name", nameDataLoader) def df1 = { env -> def loader = env.getDataLoader("name") @@ -251,10 +251,10 @@ class ProfilerTest extends Specification { } } - DataLoader nameDataLoader = DataLoaderFactory.newDataLoader(batchLoader); + DataLoader nameDataLoader = DataLoaderFactory.newDataLoader(batchLoader) - DataLoaderRegistry dataLoaderRegistry = new DataLoaderRegistry(); - dataLoaderRegistry.register("name", nameDataLoader); + DataLoaderRegistry dataLoaderRegistry = new DataLoaderRegistry() + dataLoaderRegistry.register("name", nameDataLoader) def dogDF = { env -> def loader = env.getDataLoader("name") @@ -307,17 +307,17 @@ class ProfilerTest extends Specification { def schema = TestUtil.schema(sdl, [Query: [ hello: { DataFetchingEnvironment dfe -> return "world" } as DataFetcher ]]) - Instrumentation fooInstrumentation = new Instrumentation() {}; - Instrumentation barInstrumentation = new Instrumentation() {}; + 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(); + def graphql = GraphQL.newGraphQL(schema).instrumentation(chainedInstrumentation).build() - ExecutionInput ei = ExecutionInput.newExecutionInput() + ExecutionInput ei = newExecutionInput() .query("{ hello }") .profileExecution(true) .build() @@ -355,9 +355,9 @@ class ProfilerTest extends Specification { Foo : [ bar: { DataFetchingEnvironment dfe -> dfe.source.id } as DataFetcher ]]) - def graphql = GraphQL.newGraphQL(schema).build(); + def graphql = GraphQL.newGraphQL(schema).build() - ExecutionInput ei = ExecutionInput.newExecutionInput() + ExecutionInput ei = newExecutionInput() .query("{ foo { id bar } }") .profileExecution(true) .build() @@ -392,22 +392,22 @@ class ProfilerTest extends Specification { // blocking the engine for 1ms // so that engineTotalRunningTime time is more than 1ms Thread.sleep(1) - return CompletableFuture.supplyAsync { + return supplyAsync { Thread.sleep(500) "1" } } as DataFetcher], Foo : [ id: { DataFetchingEnvironment dfe -> - return CompletableFuture.supplyAsync { + return supplyAsync { Thread.sleep(500) dfe.source } } as DataFetcher ]]) - def graphql = GraphQL.newGraphQL(schema).build(); + def graphql = GraphQL.newGraphQL(schema).build() - ExecutionInput ei = ExecutionInput.newExecutionInput() + ExecutionInput ei = newExecutionInput() .query("{ foo { id } }") .profileExecution(true) .build() @@ -456,10 +456,10 @@ class ProfilerTest extends Specification { } as DataFetcher ]]) - def graphql = GraphQL.newGraphQL(schema).build(); + def graphql = GraphQL.newGraphQL(schema).build() ExecutionId id = ExecutionId.from("myExecutionId") - ExecutionInput ei = ExecutionInput.newExecutionInput() + ExecutionInput ei = newExecutionInput() .query("{ foo { id name text } foo2: foo { id name text} }") .profileExecution(true) .executionId(id) @@ -480,9 +480,9 @@ class ProfilerTest extends Specification { "/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)"] + profilerResult.shortSummaryMap().get("dataFetcherResultTypes") == ["COMPLETABLE_FUTURE_COMPLETED" : ["count":2, "invocations":4], + "COMPLETABLE_FUTURE_NOT_COMPLETED": ["count":2, "invocations":2], + "MATERIALIZED" : ["count":2, "invocations":4]] profilerResult.shortSummaryMap().get("executionId") == "myExecutionId" } @@ -496,9 +496,9 @@ class ProfilerTest extends Specification { def schema = TestUtil.schema(sdl, [Query: [ hello: { DataFetchingEnvironment dfe -> return "world" } as DataFetcher ]]) - def graphql = GraphQL.newGraphQL(schema).build(); + def graphql = GraphQL.newGraphQL(schema).build() - ExecutionInput ei = ExecutionInput.newExecutionInput() + ExecutionInput ei = newExecutionInput() .query("query MyQuery { hello }") .profileExecution(true) .build() @@ -544,10 +544,10 @@ class ProfilerTest extends Specification { } } - DataLoader nameDataLoader = DataLoaderFactory.newDataLoader(batchLoader); + DataLoader nameDataLoader = DataLoaderFactory.newDataLoader(batchLoader) - DataLoaderRegistry dataLoaderRegistry = new DataLoaderRegistry(); - dataLoaderRegistry.register("name", nameDataLoader); + DataLoaderRegistry dataLoaderRegistry = new DataLoaderRegistry() + dataLoaderRegistry.register("name", nameDataLoader) def dogDF = { env -> return env.getDataLoader("name").load("Key1").thenCompose { From 7c5e38730c6c6ccd06e6ca2f4d204aeaca01531a Mon Sep 17 00:00:00 2001 From: dondonz <13839920+dondonz@users.noreply.github.com> Date: Fri, 1 Aug 2025 07:26:36 +1000 Subject: [PATCH 6/7] Add a few more tweaks and remove concatenation on operation name --- src/main/java/graphql/ProfilerResult.java | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index 9042fe7305..d512025cfd 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -274,9 +274,10 @@ public List getInstrumentationClasses() { public Map shortSummaryMap() { Map result = new LinkedHashMap<>(); result.put("executionId", Assert.assertNotNull(executionId).toString()); - result.put("operation", operationType + ":" + operationName); - result.put("startTime", startTime); - result.put("endTime", endTime); + result.put("operationName", operationName); + result.put("operationType", operationType.toString()); + result.put("startTimeNs", startTime); + result.put("endTimeNs", endTime); result.put("totalRunTimeNs", endTime - startTime); result.put("engineTotalRunningTimeNs", engineTotalRunningTime); result.put("totalDataFetcherInvocations", totalDataFetcherInvocations); From 0f22f0793174b0634c9a347b80348890d9cac480 Mon Sep 17 00:00:00 2001 From: dondonz <13839920+dondonz@users.noreply.github.com> Date: Fri, 1 Aug 2025 07:48:06 +1000 Subject: [PATCH 7/7] Add assert --- src/main/java/graphql/ProfilerResult.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/main/java/graphql/ProfilerResult.java b/src/main/java/graphql/ProfilerResult.java index d512025cfd..c18533ab7a 100644 --- a/src/main/java/graphql/ProfilerResult.java +++ b/src/main/java/graphql/ProfilerResult.java @@ -275,7 +275,7 @@ public Map shortSummaryMap() { Map result = new LinkedHashMap<>(); result.put("executionId", Assert.assertNotNull(executionId).toString()); result.put("operationName", operationName); - result.put("operationType", operationType.toString()); + result.put("operationType", Assert.assertNotNull(operationType).toString()); result.put("startTimeNs", startTime); result.put("endTimeNs", endTime); result.put("totalRunTimeNs", endTime - startTime);