Skip to content

Commit eef80ec

Browse files
andimarekandimarek
committed
track running time
1 parent cc1de5e commit eef80ec

7 files changed

Lines changed: 167 additions & 15 deletions

File tree

‎src/main/java/graphql/EngineRunningState.java‎

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -42,10 +42,11 @@ public EngineRunningState() {
4242
this.executionId = null;
4343
}
4444

45-
public EngineRunningState(ExecutionInput executionInput) {
45+
public EngineRunningState(ExecutionInput executionInput, Profiler profiler) {
4646
EngineRunningObserver engineRunningObserver = executionInput.getGraphQLContext().get(EngineRunningObserver.ENGINE_RUNNING_OBSERVER_KEY);
47-
if (engineRunningObserver != null) {
48-
this.engineRunningObserver = engineRunningObserver;
47+
EngineRunningObserver wrappedObserver = profiler.wrapEngineRunningObserver(engineRunningObserver);
48+
if (wrappedObserver != null) {
49+
this.engineRunningObserver = wrappedObserver;
4950
this.graphQLContext = executionInput.getGraphQLContext();
5051
this.executionId = executionInput.getExecutionId();
5152
} else {

‎src/main/java/graphql/GraphQL.java‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -421,10 +421,10 @@ public CompletableFuture<ExecutionResult> executeAsync(UnaryOperator<ExecutionIn
421421
*/
422422
public CompletableFuture<ExecutionResult> executeAsync(ExecutionInput executionInput) {
423423
Profiler profiler = executionInput.isProfileExecution() ? new ProfilerImpl(executionInput.getGraphQLContext()) : Profiler.NO_OP;
424-
profiler.start();
425-
EngineRunningState engineRunningState = new EngineRunningState(executionInput);
424+
EngineRunningState engineRunningState = new EngineRunningState(executionInput, profiler);
426425
return engineRunningState.engineRun(() -> {
427426
ExecutionInput executionInputWithId = ensureInputHasId(executionInput);
427+
profiler.setExecutionId(executionInputWithId.getExecutionId());
428428
engineRunningState.updateExecutionId(executionInputWithId.getExecutionId());
429429

430430
CompletableFuture<InstrumentationState> instrumentationStateCF = instrumentation.createStateAsync(new InstrumentationCreateStateParameters(this.graphQLSchema, executionInputWithId));

‎src/main/java/graphql/Profiler.java‎

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,8 +1,11 @@
11
package graphql;
22

3+
import graphql.execution.EngineRunningObserver;
4+
import graphql.execution.ExecutionId;
35
import graphql.execution.ResultPath;
46
import graphql.schema.DataFetcher;
57
import org.jspecify.annotations.NullMarked;
8+
import org.jspecify.annotations.Nullable;
69

710
@Internal
811
@NullMarked
@@ -25,7 +28,15 @@ default void subSelectionCount(int size) {
2528

2629
}
2730

31+
default void setExecutionId(ExecutionId executionId) {
32+
33+
}
34+
2835
default void fieldFetched(Object fetchedObject, DataFetcher<?> dataFetcher, ResultPath path) {
2936

3037
}
38+
39+
default @Nullable EngineRunningObserver wrapEngineRunningObserver(EngineRunningObserver engineRunningObserver) {
40+
return engineRunningObserver;
41+
}
3142
}

‎src/main/java/graphql/ProfilerImpl.java‎

Lines changed: 42 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,16 +1,23 @@
11
package graphql;
22

3+
import graphql.execution.EngineRunningObserver;
4+
import graphql.execution.ExecutionId;
35
import graphql.execution.ResultPath;
46
import graphql.schema.DataFetcher;
57
import graphql.schema.PropertyDataFetcher;
68
import graphql.schema.SingletonPropertyDataFetcher;
79
import org.jspecify.annotations.NullMarked;
810

11+
import java.util.concurrent.atomic.AtomicLong;
12+
913
@Internal
1014
@NullMarked
1115
public class ProfilerImpl implements Profiler {
1216

13-
volatile long startTime;
17+
private volatile long startTime;
18+
private volatile long endTime;
19+
private volatile long lastStartTime;
20+
private final AtomicLong engineTotalRunningTime = new AtomicLong();
1421

1522

1623
final ProfilerResult profilerResult = new ProfilerResult();
@@ -20,8 +27,8 @@ public ProfilerImpl(GraphQLContext graphQLContext) {
2027
}
2128

2229
@Override
23-
public void start() {
24-
startTime = System.nanoTime();
30+
public void setExecutionId(ExecutionId executionId) {
31+
profilerResult.setExecutionId(executionId);
2532
}
2633

2734
@Override
@@ -37,4 +44,36 @@ public void fieldFetched(Object fetchedObject, DataFetcher<?> dataFetcher, Resul
3744
}
3845
profilerResult.setDataFetcherType(key, dataFetcherType);
3946
}
47+
48+
@Override
49+
public EngineRunningObserver wrapEngineRunningObserver(EngineRunningObserver engineRunningObserver) {
50+
// nothing to wrap here
51+
return new EngineRunningObserver() {
52+
@Override
53+
public void runningStateChanged(ExecutionId executionId, GraphQLContext graphQLContext, RunningState runningState) {
54+
runningStateChangedImpl(executionId, graphQLContext, runningState);
55+
if (engineRunningObserver != null) {
56+
engineRunningObserver.runningStateChanged(executionId, graphQLContext, runningState);
57+
}
58+
}
59+
};
60+
}
61+
62+
private void runningStateChangedImpl(ExecutionId executionId, GraphQLContext graphQLContext, EngineRunningObserver.RunningState runningState) {
63+
long now = System.nanoTime();
64+
if (runningState == EngineRunningObserver.RunningState.RUNNING_START) {
65+
startTime = now;
66+
lastStartTime = startTime;
67+
} else if (runningState == EngineRunningObserver.RunningState.NOT_RUNNING_FINISH) {
68+
endTime = now;
69+
engineTotalRunningTime.set(engineTotalRunningTime.get() + (endTime - lastStartTime));
70+
profilerResult.setTimes(startTime, endTime, engineTotalRunningTime.get());
71+
} else if (runningState == EngineRunningObserver.RunningState.RUNNING) {
72+
lastStartTime = now;
73+
} else if (runningState == EngineRunningObserver.RunningState.NOT_RUNNING) {
74+
engineTotalRunningTime.set(engineTotalRunningTime.get() + (now - lastStartTime));
75+
} else {
76+
Assert.assertShouldNeverHappen();
77+
}
78+
}
4079
}

‎src/main/java/graphql/ProfilerResult.java‎

Lines changed: 52 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,7 @@
11
package graphql;
22

3+
import graphql.execution.ExecutionId;
4+
35
import java.util.LinkedHashSet;
46
import java.util.Map;
57
import java.util.Set;
@@ -9,16 +11,22 @@
911
@ExperimentalApi
1012
public class ProfilerResult {
1113

12-
public static String PROFILER_CONTEXT_KEY = "__GJ_PROFILER";
14+
public static final String PROFILER_CONTEXT_KEY = "__GJ_PROFILER";
15+
16+
private volatile ExecutionId executionId;
17+
private long startTime;
18+
private long endTime;
19+
private long engineTotalRunningTime;
20+
private final Set<String> fieldsFetched = ConcurrentHashMap.newKeySet();
1321

1422
private final AtomicInteger totalDataFetcherInvocations = new AtomicInteger();
1523
private final AtomicInteger totalPropertyDataFetcherInvocations = new AtomicInteger();
1624

1725

18-
private final Set<String> fieldsFetched = ConcurrentHashMap.newKeySet();
1926
private final Map<String, Integer> dataFetcherInvocationCount = new ConcurrentHashMap<>();
2027
private final Map<String, DataFetcherType> dataFetcherTypeMap = new ConcurrentHashMap<>();
2128

29+
2230
public enum DataFetcherType {
2331
PROPERTY_DATA_FETCHER,
2432
CUSTOM
@@ -31,7 +39,8 @@ public enum ResultType {
3139

3240
}
3341

34-
private Map<String, ResultType> queryPathToResultType;
42+
43+
// setters are package private to prevent exposure
3544

3645
void setDataFetcherType(String key, DataFetcherType dataFetcherType) {
3746
dataFetcherTypeMap.putIfAbsent(key, dataFetcherType);
@@ -49,6 +58,16 @@ void addFieldFetched(String fieldPath) {
4958
fieldsFetched.add(fieldPath);
5059
}
5160

61+
void setExecutionId(ExecutionId executionId) {
62+
this.executionId = executionId;
63+
}
64+
65+
void setTimes(long startTime, long endTime, long engineTotalRunningTime) {
66+
this.startTime = startTime;
67+
this.endTime = endTime;
68+
this.engineTotalRunningTime = engineTotalRunningTime;
69+
}
70+
5271

5372
public Set<String> getFieldsFetched() {
5473
return fieldsFetched;
@@ -87,4 +106,34 @@ public int getTotalCustomDataFetcherInvocations() {
87106
return totalDataFetcherInvocations.get() - totalPropertyDataFetcherInvocations.get();
88107
}
89108

109+
public long getStartTime() {
110+
return startTime;
111+
}
112+
113+
public long getEndTime() {
114+
return endTime;
115+
}
116+
117+
public long getEngineTotalRunningTime() {
118+
return engineTotalRunningTime;
119+
}
120+
121+
public long getTotalExecutionTime() {
122+
return endTime - startTime;
123+
}
124+
125+
@Override
126+
public String toString() {
127+
return "ProfilerResult{" +
128+
"executionId=" + executionId +
129+
", startTime=" + startTime +
130+
", endTime=" + endTime +
131+
", engineTotalRunningTime=" + engineTotalRunningTime +
132+
", fieldsFetched=" + fieldsFetched +
133+
", totalDataFetcherInvocations=" + totalDataFetcherInvocations +
134+
", totalPropertyDataFetcherInvocations=" + totalPropertyDataFetcherInvocations +
135+
", dataFetcherInvocationCount=" + dataFetcherInvocationCount +
136+
", dataFetcherTypeMap=" + dataFetcherTypeMap +
137+
'}';
138+
}
90139
}

‎src/test/groovy/graphql/ProfilerTest.groovy‎

Lines changed: 52 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,9 @@ import graphql.schema.DataFetcher
44
import graphql.schema.DataFetchingEnvironment
55
import spock.lang.Specification
66

7+
import java.time.Duration
8+
import java.util.concurrent.CompletableFuture
9+
710
class ProfilerTest extends Specification {
811

912

@@ -74,4 +77,53 @@ class ProfilerTest extends Specification {
7477
profilerResult.getTotalPropertyDataFetcherInvocations() == 3
7578
}
7679

80+
def "records timing"() {
81+
given:
82+
def sdl = '''
83+
type Query {
84+
foo: Foo
85+
}
86+
type Foo {
87+
id: String
88+
}
89+
'''
90+
def schema = TestUtil.schema(sdl, [
91+
Query: [
92+
foo: { DataFetchingEnvironment dfe ->
93+
return CompletableFuture.supplyAsync {
94+
Thread.sleep(500)
95+
"1"
96+
}
97+
} as DataFetcher],
98+
Foo : [
99+
id: { DataFetchingEnvironment dfe ->
100+
return CompletableFuture.supplyAsync {
101+
Thread.sleep(500)
102+
dfe.source
103+
}
104+
} as DataFetcher
105+
]])
106+
def graphql = GraphQL.newGraphQL(schema).build();
107+
108+
ExecutionInput ei = ExecutionInput.newExecutionInput()
109+
.query("{ foo { id } }")
110+
.profileExecution(true)
111+
.build()
112+
113+
when:
114+
def result = graphql.execute(ei)
115+
def profilerResult = ei.getGraphQLContext().get(ProfilerResult.PROFILER_CONTEXT_KEY) as ProfilerResult
116+
117+
then:
118+
result.getData() == [foo: [id: "1"]]
119+
// the total execution time must be more than 1 second,
120+
// the engine should take less than 500ms
121+
profilerResult.getTotalExecutionTime() > Duration.ofSeconds(1).toNanos()
122+
profilerResult.getEngineTotalRunningTime() > Duration.ofMillis(1).toNanos()
123+
profilerResult.getEngineTotalRunningTime() < Duration.ofMillis(500).toNanos()
124+
125+
126+
}
127+
128+
77129
}

‎src/test/groovy/graphql/execution/ExecutionTest.groovy‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -53,7 +53,7 @@ class ExecutionTest extends Specification {
5353
def document = parser.parseDocument(query)
5454

5555
when:
56-
execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput), Profiler.NO_OP)
56+
execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput, Profiler.NO_OP), Profiler.NO_OP)
5757

5858
then:
5959
queryStrategy.execute == 1
@@ -73,7 +73,7 @@ class ExecutionTest extends Specification {
7373
def document = parser.parseDocument(query)
7474

7575
when:
76-
execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput), Profiler.NO_OP)
76+
execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput, Profiler.NO_OP), Profiler.NO_OP)
7777

7878
then:
7979
queryStrategy.execute == 0
@@ -93,7 +93,7 @@ class ExecutionTest extends Specification {
9393
def document = parser.parseDocument(query)
9494

9595
when:
96-
execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput), Profiler.NO_OP)
96+
execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput, Profiler.NO_OP), Profiler.NO_OP)
9797

9898
then:
9999
queryStrategy.execute == 0
@@ -130,7 +130,7 @@ class ExecutionTest extends Specification {
130130

131131

132132
when:
133-
execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput), Profiler.NO_OP)
133+
execution.execute(document, MutationSchema.schema, ExecutionId.generate(), emptyExecutionInput, instrumentationState, new EngineRunningState(emptyExecutionInput, Profiler.NO_OP), Profiler.NO_OP)
134134

135135
then:
136136
queryStrategy.execute == 0

0 commit comments

Comments
 (0)