track running time

dondonz · Jul 21, 2025 · May 19, 2025 · May 19, 2025 · May 20, 2025 · May 20, 2025
commit eef80ecbb53eb9b2f78f463190d6109d33f40a20
diff --git 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
@@ -421,10 +421,10 @@ public CompletableFuture<ExecutionResult> executeAsync(UnaryOperator<ExecutionIn
      */
     public CompletableFuture<ExecutionResult> 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<InstrumentationState> instrumentationStateCF = instrumentation.createStateAsync(new InstrumentationCreateStateParameters(this.graphQLSchema, executionInputWithId));

diff --git 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
@@ -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
@@ -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<String> fieldsFetched = ConcurrentHashMap.newKeySet();
 
     private final AtomicInteger totalDataFetcherInvocations = new AtomicInteger();
     private final AtomicInteger totalPropertyDataFetcherInvocations = new AtomicInteger();
 
 
-    private final Set<String> fieldsFetched = ConcurrentHashMap.newKeySet();
     private final Map<String, Integer> dataFetcherInvocationCount = new ConcurrentHashMap<>();
     private final Map<String, DataFetcherType> dataFetcherTypeMap = new ConcurrentHashMap<>();
 
+
     public enum DataFetcherType {
         PROPERTY_DATA_FETCHER,
         CUSTOM
@@ -31,7 +39,8 @@ public enum ResultType {
 
     }
 
-    private Map<String, ResultType> 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<String> 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
@@ -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
@@ -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