From f973812a5aa15a79686abba8d791eb64bbf5425a Mon Sep 17 00:00:00 2001 From: dondonz <13839920+dondonz@users.noreply.github.com> Date: Tue, 5 Aug 2025 14:42:20 +1000 Subject: [PATCH 1/4] Add first cut of documentation --- documentation/profiler.md | 112 ++++++++++++++++++++++++++++++++++++++ 1 file changed, 112 insertions(+) create mode 100644 documentation/profiler.md diff --git a/documentation/profiler.md b/documentation/profiler.md new file mode 100644 index 0000000..a30b1f0 --- /dev/null +++ b/documentation/profiler.md @@ -0,0 +1,112 @@ +--- +title: "Profiling requests" +date: 2025-08-05T12:52:46+10:00 +description: How to avoid the dreaded N+1 calls for data and make your graphql system more efficient +--- + +# Profiling GraphQL requests + +We've introduced a new query profiling feature to help you understand the performance characteristics of your GraphQL executions. It provides detailed insights into data fetcher calls, data loader usage, and execution timing. This guide will show you how to use it and interpret the results. + +The Profiler is available in all versions after v25.0.beta-5. If you're not using a beta version, it will be included in the official v25.0 release. + +## Enabling the Profiler + +To enable profiling for a GraphQL execution, you need to set a flag on your `ExecutionInput`. It's as simple as calling `.profileExecution(true)` when building it. + +```java +import graphql.ExecutionInput; +import graphql.GraphQL; + +// ... +GraphQL graphql = GraphQL.newGraphQL(schema).build(); + +ExecutionInput executionInput = ExecutionInput.newExecutionInput() + .query("{ hello }") + .profileExecution(true) // Enable profiling + .build(); + +graphql.execute(executionInput); +``` + +## Accessing the Profiler Results + +The profiling results are stored in the `GraphQLContext` associated with your `ExecutionInput`. After the execution is complete, you can retrieve the `ProfilerResult` object from the context. + +The result object is stored under the key `ProfilerResult.PROFILER_CONTEXT_KEY`. + +```java +import graphql.ExecutionInput; +import graphql.ExecutionResult; +import graphql.GraphQL; +import graphql.ProfilerResult; + +// ... +ExecutionInput executionInput = /* ... see above ... */ +ExecutionResult executionResult = graphql.execute(executionInput); + +ProfilerResult profilerResult = executionInput.getGraphQLContext().get(ProfilerResult.PROFILER_CONTEXT_KEY); + +if (profilerResult != null) { + // You now have access to the profiling data + Map summary = profilerResult.shortSummaryMap(); + System.out.println(summary); +} +``` + +## Understanding the Profiler Results + +The `ProfilerResult` object contains a wealth of information. A great way to get a quick overview is by using the `shortSummaryMap()` method. It returns a map with key metrics about the execution. Let's break down what each key means. + +### The Short Summary Map + +Here's a detailed explanation of the fields you'll find in the map returned by `shortSummaryMap()`: + +| Key | Type | Description | +| ------------------------------------- | ----------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `executionId` | `String` | The unique ID for this GraphQL execution. | +| `operationName` | `String` | The name of the operation, if one was provided in the query (e.g., `query MyQuery { ... }`). | +| `operationType` | `String` | The type of operation, such as `QUERY`, `MUTATION`, or `SUBSCRIPTION`. | +| `startTimeNs` | `long` | The system monotonic time in nanoseconds when the execution started. | +| `endTimeNs` | `long` | The system monotonic time in nanoseconds when the execution finished. | +| `totalRunTimeNs` | `long` | The total wall-clock time of the execution (`endTimeNs - startTimeNs`). This includes time spent waiting for asynchronous operations like database calls or external API requests within your data fetchers. | +| `engineTotalRunningTimeNs` | `long` | The total time the GraphQL engine spent actively running on a thread. This is like the "CPU time" of the execution and excludes time spent waiting for `CompletableFuture`s to complete. Comparing this with `totalRunTimeNs` can give you a good idea of how much time is spent on I/O. | +| `totalDataFetcherInvocations` | `int` | The total number of times any data fetcher was invoked. | +| `totalCustomDataFetcherInvocations` | `int` | The number of invocations for data fetchers you've written yourself (i.e., not the built-in `PropertyDataFetcher`). This is often the most interesting data fetcher metric. | +| `totalTrivialDataFetcherInvocations` | `int` | The number of invocations for the built-in `PropertyDataFetcher`, which simply retrieves a property from a POJO. | +| `totalWrappedTrivialDataFetcherInvocations` | `int` | The number of invocations for data fetchers that wrap a `PropertyDataFetcher`. This usually happens when you use instrumentation to wrap data fetchers. | +| `fieldsFetchedCount` | `int` | The number of unique fields fetched during the execution. | +| `dataLoaderChainingEnabled` | `boolean` | `true` if the experimental data loader chaining feature was enabled for this execution. | +| `dataLoaderLoadInvocations` | `Map` | A map where keys are data loader names and values are the number of times `load()` was called on them. Note that this counts all `load()` calls, including those that hit the data loader cache. | +| `oldStrategyDispatchingAll` | `Set` | An advanced metric related to an older data loader dispatching strategy. It contains the execution levels where all data loaders were dispatched at once. | +| `dispatchEvents` | `List` | A list of events, one for each time a data loader was dispatched. See below for details. | +| `instrumentationClasses` | `List` | A list of the fully qualified class names of the `Instrumentation` implementations used during this execution. | +| `dataFetcherResultTypes` | `Map` | A summary of the types of values returned by your custom data fetchers. See below for details. | + +#### `dispatchEvents` + +This is a list of maps, each detailing a `DataLoader` dispatch event. + +| Key | Type | Description | +| -------------- | -------- | -------------------------------------------------------------------- | +| `type` | `String` | The type of dispatch. Can be `LEVEL_STRATEGY_DISPATCH`, `CHAINED_STRATEGY_DISPATCH`, `DELAYED_DISPATCH`, `CHAINED_DELAYED_DISPATCH`, or `MANUAL_DISPATCH`. | +| `dataLoader` | `String` | The name of the `DataLoader` that was dispatched. | +| `level` | `int` | The execution strategy level at which the dispatch occurred. | +| `keyCount` | `int` | The number of keys that were dispatched in this batch. | + +#### `dataFetcherResultTypes` + +This map gives you insight into the nature of your data fetchers' return values. This is especially useful for understanding the asynchronous behavior of your schema. + +The keys are `COMPLETABLE_FUTURE_COMPLETED`, `COMPLETABLE_FUTURE_NOT_COMPLETED`, and `MATERIALIZED`. +Each key maps to another map with two keys: +* `count`: The number of unique fields with data fetchers that returned this result type. +* `invocations`: The total number of invocations across all fields that returned this result type. + +Here's what the result types mean: + +| Result Type | Meaning | +| ---------------------------------- | --------------------------------------------------------------------------------------------- | +| `COMPLETABLE_FUTURE_COMPLETED` | The data fetcher returned a `CompletableFuture` that was already completed when it was returned. | +| `COMPLETABLE_FUTURE_NOT_COMPLETED` | The data fetcher returned an incomplete `CompletableFuture`, indicating asynchronous work. | +| `MATERIALIZED` | The data fetcher returned a simple value (i.e., not a `CompletableFuture`). | From 4430712185c6ad5b16c345860d5a96dd6280d0a0 Mon Sep 17 00:00:00 2001 From: dondonz <13839920+dondonz@users.noreply.github.com> Date: Tue, 5 Aug 2025 15:17:13 +1000 Subject: [PATCH 2/4] Adding edits --- documentation/profiler.md | 63 ++++++++++++++++++++------------------- 1 file changed, 32 insertions(+), 31 deletions(-) diff --git a/documentation/profiler.md b/documentation/profiler.md index a30b1f0..0b7034e 100644 --- a/documentation/profiler.md +++ b/documentation/profiler.md @@ -6,9 +6,9 @@ description: How to avoid the dreaded N+1 calls for data and make your graphql s # Profiling GraphQL requests -We've introduced a new query profiling feature to help you understand the performance characteristics of your GraphQL executions. It provides detailed insights into data fetcher calls, data loader usage, and execution timing. This guide will show you how to use it and interpret the results. +We've introduced a new profiling feature to help you understand the performance of your GraphQL executions. It provides detailed insights into DataFetcher calls, Dataloader usage, and execution timing. This guide will show you how to use it and interpret the results. -The Profiler is available in all versions after v25.0.beta-5. If you're not using a beta version, it will be included in the official v25.0 release. +The Profiler is available in all versions after v25.0.beta-5. It will also be included in the forthcoming official v25.0 release. ## Enabling the Profiler @@ -22,7 +22,7 @@ import graphql.GraphQL; GraphQL graphql = GraphQL.newGraphQL(schema).build(); ExecutionInput executionInput = ExecutionInput.newExecutionInput() - .query("{ hello }") + .query("query Hello { world }") .profileExecution(true) // Enable profiling .build(); @@ -48,40 +48,41 @@ ExecutionResult executionResult = graphql.execute(executionInput); ProfilerResult profilerResult = executionInput.getGraphQLContext().get(ProfilerResult.PROFILER_CONTEXT_KEY); if (profilerResult != null) { - // You now have access to the profiling data Map summary = profilerResult.shortSummaryMap(); - System.out.println(summary); + System.out.println(summary); // or log } ``` +You could alternatively access and log the request's `ProfilerResult` from an `Instrumentation`. + ## Understanding the Profiler Results -The `ProfilerResult` object contains a wealth of information. A great way to get a quick overview is by using the `shortSummaryMap()` method. It returns a map with key metrics about the execution. Let's break down what each key means. +A great way to get a quick overview about `ProfilerResult` is by using the `shortSummaryMap()` method. It returns a map with key metrics about the execution, which you can use for logging. Let's break down what each key means. -### The Short Summary Map +### The ProfilerResult Short Summary Map Here's a detailed explanation of the fields you'll find in the map returned by `shortSummaryMap()`: -| Key | Type | Description | -| ------------------------------------- | ----------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| `executionId` | `String` | The unique ID for this GraphQL execution. | -| `operationName` | `String` | The name of the operation, if one was provided in the query (e.g., `query MyQuery { ... }`). | -| `operationType` | `String` | The type of operation, such as `QUERY`, `MUTATION`, or `SUBSCRIPTION`. | -| `startTimeNs` | `long` | The system monotonic time in nanoseconds when the execution started. | -| `endTimeNs` | `long` | The system monotonic time in nanoseconds when the execution finished. | -| `totalRunTimeNs` | `long` | The total wall-clock time of the execution (`endTimeNs - startTimeNs`). This includes time spent waiting for asynchronous operations like database calls or external API requests within your data fetchers. | +| Key | Type | Description | +| ------------------------------------- | ----------- |------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------| +| `executionId` | `String` | The unique ID for this GraphQL execution. | +| `operationName` | `String` | The name of the operation, if one was provided in the query (e.g., `query MyQuery { ... }`). | +| `operationType` | `String` | The type of operation, such as `QUERY`, `MUTATION`, or `SUBSCRIPTION`. | +| `startTimeNs` | `long` | The system time in nanoseconds when the execution started. | +| `endTimeNs` | `long` | The system time in nanoseconds when the execution finished. | +| `totalRunTimeNs` | `long` | The total wall-clock time of the execution (`endTimeNs - startTimeNs`). This includes time spent waiting for asynchronous operations like database calls or external API requests within your DataFetchers. | | `engineTotalRunningTimeNs` | `long` | The total time the GraphQL engine spent actively running on a thread. This is like the "CPU time" of the execution and excludes time spent waiting for `CompletableFuture`s to complete. Comparing this with `totalRunTimeNs` can give you a good idea of how much time is spent on I/O. | -| `totalDataFetcherInvocations` | `int` | The total number of times any data fetcher was invoked. | -| `totalCustomDataFetcherInvocations` | `int` | The number of invocations for data fetchers you've written yourself (i.e., not the built-in `PropertyDataFetcher`). This is often the most interesting data fetcher metric. | -| `totalTrivialDataFetcherInvocations` | `int` | The number of invocations for the built-in `PropertyDataFetcher`, which simply retrieves a property from a POJO. | -| `totalWrappedTrivialDataFetcherInvocations` | `int` | The number of invocations for data fetchers that wrap a `PropertyDataFetcher`. This usually happens when you use instrumentation to wrap data fetchers. | -| `fieldsFetchedCount` | `int` | The number of unique fields fetched during the execution. | -| `dataLoaderChainingEnabled` | `boolean` | `true` if the experimental data loader chaining feature was enabled for this execution. | -| `dataLoaderLoadInvocations` | `Map` | A map where keys are data loader names and values are the number of times `load()` was called on them. Note that this counts all `load()` calls, including those that hit the data loader cache. | -| `oldStrategyDispatchingAll` | `Set` | An advanced metric related to an older data loader dispatching strategy. It contains the execution levels where all data loaders were dispatched at once. | -| `dispatchEvents` | `List` | A list of events, one for each time a data loader was dispatched. See below for details. | -| `instrumentationClasses` | `List` | A list of the fully qualified class names of the `Instrumentation` implementations used during this execution. | -| `dataFetcherResultTypes` | `Map` | A summary of the types of values returned by your custom data fetchers. See below for details. | +| `totalDataFetcherInvocations` | `int` | The total number of times any DataFetcher was invoked. | +| `totalCustomDataFetcherInvocations` | `int` | The number of invocations for DataFetchers you've written yourself (i.e., not the built-in `PropertyDataFetcher`). | +| `totalTrivialDataFetcherInvocations` | `int` | The number of invocations for the built-in `PropertyDataFetcher`. | +| `totalWrappedTrivialDataFetcherInvocations` | `int` | The number of invocations for DataFetchers that wrap a `PropertyDataFetcher`. | +| `fieldsFetchedCount` | `int` | The number of unique fields fetched during the execution. | +| `dataLoaderChainingEnabled` | `boolean` | `true` if the experimental Dataloader chaining feature was enabled for this execution. | +| `dataLoaderLoadInvocations` | `Map` | A map where keys are Dataloader names and values are the number of times `load()` was called on them. Note that this counts all `load()` calls, including those that hit the Dataloader cache. | +| `oldStrategyDispatchingAll` | `Set` | If Chained DataLoaders are not used, the older dispatching strategy is used instead. This key lists the levels where DataLoaders were dispatched. | +| `dispatchEvents` | `List` | A list of events, one for each time a Dataloader was dispatched. See below for details. | +| `instrumentationClasses` | `List` | A list of the class names of the `Instrumentation`s used during this execution. | +| `dataFetcherResultTypes` | `Map` | A summary of the types of values returned by your custom DataFetchers. See below for details. | #### `dispatchEvents` @@ -96,17 +97,17 @@ This is a list of maps, each detailing a `DataLoader` dispatch event. #### `dataFetcherResultTypes` -This map gives you insight into the nature of your data fetchers' return values. This is especially useful for understanding the asynchronous behavior of your schema. +This map gives you more information into the type of your DataFetchers' return values. The keys are `COMPLETABLE_FUTURE_COMPLETED`, `COMPLETABLE_FUTURE_NOT_COMPLETED`, and `MATERIALIZED`. Each key maps to another map with two keys: -* `count`: The number of unique fields with data fetchers that returned this result type. +* `count`: The number of unique fields with DataFetchers that returned this result type. * `invocations`: The total number of invocations across all fields that returned this result type. Here's what the result types mean: | Result Type | Meaning | | ---------------------------------- | --------------------------------------------------------------------------------------------- | -| `COMPLETABLE_FUTURE_COMPLETED` | The data fetcher returned a `CompletableFuture` that was already completed when it was returned. | -| `COMPLETABLE_FUTURE_NOT_COMPLETED` | The data fetcher returned an incomplete `CompletableFuture`, indicating asynchronous work. | -| `MATERIALIZED` | The data fetcher returned a simple value (i.e., not a `CompletableFuture`). | +| `COMPLETABLE_FUTURE_COMPLETED` | The DataFetcher returned a `CompletableFuture` that was already completed when it was returned. | +| `COMPLETABLE_FUTURE_NOT_COMPLETED` | The DataFetcher returned an incomplete `CompletableFuture`. | +| `MATERIALIZED` | The DataFetcher returned a simple value (i.e., not a `CompletableFuture`). | From e1d61178f90d64c6dd505f0090f537f904d436f5 Mon Sep 17 00:00:00 2001 From: dondonz <13839920+dondonz@users.noreply.github.com> Date: Tue, 5 Aug 2025 15:54:24 +1000 Subject: [PATCH 3/4] Tidy up --- documentation/profiler.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/documentation/profiler.md b/documentation/profiler.md index 0b7034e..8028157 100644 --- a/documentation/profiler.md +++ b/documentation/profiler.md @@ -49,7 +49,7 @@ ProfilerResult profilerResult = executionInput.getGraphQLContext().get(ProfilerR if (profilerResult != null) { Map summary = profilerResult.shortSummaryMap(); - System.out.println(summary); // or log + System.out.println(summary); // or log as you prefer } ``` From 6aa1986d1688fb0d22226b9379a03c17aba202f1 Mon Sep 17 00:00:00 2001 From: dondonz <13839920+dondonz@users.noreply.github.com> Date: Wed, 6 Aug 2025 07:24:32 +1000 Subject: [PATCH 4/4] Tidy up --- documentation/profiler.md | 1 - 1 file changed, 1 deletion(-) diff --git a/documentation/profiler.md b/documentation/profiler.md index 8028157..8a58fa6 100644 --- a/documentation/profiler.md +++ b/documentation/profiler.md @@ -1,7 +1,6 @@ --- title: "Profiling requests" date: 2025-08-05T12:52:46+10:00 -description: How to avoid the dreaded N+1 calls for data and make your graphql system more efficient --- # Profiling GraphQL requests