Skip to content

Commit f11aeed

Browse files
andimarekandimarek
committed
wip
1 parent 12ad6ba commit f11aeed

File tree

2 files changed

+18
-6
lines changed

2 files changed

+18
-6
lines changed

‎agent-test/src/test/java/graphql/test/AgentTest.java‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,9 @@ void test() {
2828
@Test
2929
void testBatchLoader() {
3030
ExecutionTrackingResult executionTrackingResult = TestQuery.executeBatchedQuery();
31+
TestQuery.executeBatchedQuery();
32+
TestQuery.executeBatchedQuery();
33+
TestQuery.executeBatchedQuery();
3134
// assertThat(executionTrackingResult.dataFetcherCount()).isEqualTo(9);
3235
// assertThat(executionTrackingResult.getTime("/issues")).isGreaterThan(100);
3336
// assertThat(executionTrackingResult.getDfResultTypes("/issues[0]/author"))

‎agent/src/main/java/graphql/agent/GraphQLJavaAgent.java‎

Lines changed: 15 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -45,7 +45,7 @@ public static class ExecutionData {
4545
public final Map<ResultPath, Long> timePerPath = new ConcurrentHashMap<>();
4646
public final Map<ResultPath, Long> finishedTimePerPath = new ConcurrentHashMap<>();
4747
public final Map<ResultPath, String> finishedThreadPerPath = new ConcurrentHashMap<>();
48-
public final Map<ResultPath, String> invocationThreadPerPath = new ConcurrentHashMap<>();
48+
public final Map<ResultPath, String> startInvocationThreadPerPath = new ConcurrentHashMap<>();
4949
private final Map<ResultPath, DFResultType> dfResultTypes = new ConcurrentHashMap<>();
5050

5151
public static class BatchLoadingCall {
@@ -69,7 +69,8 @@ public String print(String executionId) {
6969
s.append("Nonblocking fields count: ").append(dfResultTypes.values().stream().filter(dfResultType -> dfResultType == PENDING).count()).append("\n");
7070
s.append("DataLoaders used: ").append(dataLoaderToName.size()).append("\n");
7171
s.append("DataLoader names: ").append(dataLoaderToName.values()).append("\n");
72-
s.append("start thread: '" + startThread.get() + "' end thread: '" + endThread.get()).append("'\n");
72+
s.append("start execution thread: '").append(startThread.get()).append("'\n");
73+
s.append("end execution thread: '").append(endThread.get()).append("'\n");
7374
s.append("BatchLoader calls details: ").append("\n");
7475
s.append("==========================").append("\n");
7576
for (String dataLoaderName : dataLoaderNameToBatchCall.keySet()) {
@@ -88,8 +89,13 @@ public String print(String executionId) {
8889
s.append("Field details:").append("\n");
8990
s.append("===============").append("\n");
9091
for (ResultPath path : timePerPath.keySet()) {
91-
s.append("Field: '").append(path).append("' took: ").append(timePerPath.get(path)).append(" nano seconds, ").append("\n");
92+
s.append("Field: '").append(path).append("'\n");
93+
s.append("invocation time: ").append(timePerPath.get(path)).append(" nano seconds, ").append("\n");
94+
s.append("completion time: ").append(finishedTimePerPath.get(path)).append(" nano seconds, ").append("\n");
9295
s.append("Result type: ").append(dfResultTypes.get(path)).append("\n");
96+
s.append("invoked in thread: ").append(startInvocationThreadPerPath.get(path)).append("\n");
97+
s.append("finished in thread: ").append(finishedThreadPerPath.get(path)).append("\n");
98+
s.append("-------------\n");
9399
}
94100
s.append("==========================").append("\n");
95101
s.append("==========================").append("\n");
@@ -265,6 +271,7 @@ public void accept(Object o, Throwable throwable) {
265271
ExecutionId executionId = executionContext.getExecutionId();
266272
GraphQLJavaAgent.ExecutionData executionData = GraphQLJavaAgent.executionIdToData.get(executionId);
267273
ResultPath path = parameters.getPath();
274+
System.out.println("finished " + path);
268275
executionData.finishedTimePerPath.put(path, System.nanoTime() - startTime);
269276
executionData.finishedThreadPerPath.put(path, Thread.currentThread().getName());
270277
}
@@ -275,13 +282,13 @@ public static void invokeDataFetcherEnter(@Advice.Argument(0) ExecutionContext e
275282
@Advice.Argument(1) ExecutionStrategyParameters parameters) {
276283
GraphQLJavaAgent.ExecutionData executionData = GraphQLJavaAgent.executionIdToData.get(executionContext.getExecutionId());
277284
executionData.start(parameters.getPath(), System.nanoTime());
278-
executionData.invocationThreadPerPath.put(parameters.getPath(), Thread.currentThread().getName());
285+
executionData.startInvocationThreadPerPath.put(parameters.getPath(), Thread.currentThread().getName());
279286
}
280287

281288
@Advice.OnMethodExit
282289
public static void invokeDataFetcherExit(@Advice.Argument(0) ExecutionContext executionContext,
283290
@Advice.Argument(1) ExecutionStrategyParameters parameters,
284-
@Advice.Return CompletableFuture<Object> result) {
291+
@Advice.Return(readOnly = false) CompletableFuture<Object> result) {
285292
// ExecutionTrackingResult executionTrackingResult = executionContext.getGraphQLContext().get(EXECUTION_TRACKING_KEY);
286293
GraphQLJavaAgent.ExecutionData executionData = GraphQLJavaAgent.executionIdToData.get(executionContext.getExecutionId());
287294
ResultPath path = parameters.getPath();
@@ -298,7 +305,9 @@ public static void invokeDataFetcherExit(@Advice.Argument(0) ExecutionContext ex
298305
} else {
299306
executionData.setDfResultTypes(path, PENDING);
300307
}
301-
result.whenComplete(new DataFetcherFinishedHandler(executionContext, parameters, startTime));
308+
// overriding the result to make sure the finished handler is called first when the DF is finished
309+
// otherwise it is a completion tree instead of chain
310+
result = result.whenComplete(new DataFetcherFinishedHandler(executionContext, parameters, startTime));
302311
}
303312

304313
}

0 commit comments

Comments
 (0)