Some CPU overhead from ChainedInstrumentation

[DanielThomas]

Describe the bug

We register more than one instrumentation as part of our DGS framework, which leads to ChainedInstrumentation being used. This class shows as a hotspot for field instrumentation in particular. In the case of the application I was looking at, I'd estimate it's 5-8% of the CPU overhead while satisfying queries:

Data fetching for this service is all GRPC/Netty/EVCache, so graphql-java hotspots become more visible that they might otherwise be; this is very likely the worst case for this class.

To Reproduce

Note the overhead of field instrumentation when using chained instrumentations, due to the frequency of beginField calls for any non-trivial query.

[rrva]

We use this workaround

/**
 * ChainedInstrumentation is slow, so we use this class to more manually combine multiple instrumentations into one.
 */
class FastGraphQLInstrumentations(
    private val searchQueryCacheTTLInstrumentation: SearchQueryCacheTTLInstrumentation,
    private val disableCacheInstrumentation: DisableCacheInstrumentation,
    private val modifyHttpStatusCodeInstrumentation: ModifyHttpStatusCodeInstrumentation
) : SimplePerformantInstrumentation() {

    override fun instrumentExecutionResult(
        executionResult: ExecutionResult?,
        parameters: InstrumentationExecutionParameters?,
        state: InstrumentationState?
    ): CompletableFuture<ExecutionResult> {
        val queryContext = parameters?.graphQLContext?.get<QueryContext>("queryContext")
        if (queryContext != null && executionResult != null) {
            val result = modifyHttpStatusCodeInstrumentation.modifyHttpStatusCode(queryContext, executionResult)
            if (result != null) {
                return result
            }
        }
        if (queryContext != null && executionResult != null) {
            val result = searchQueryCacheTTLInstrumentation.addCacheTTLForShortSearchQueries(queryContext, executionResult)
            if (result != null) {
                return result
            }
        }
        if (queryContext != null && executionResult != null) {
            val result = disableCacheInstrumentation.disableCaching(queryContext, executionResult)
            if (result != null) {
                return result
            }
        }
        return super.instrumentExecutionResult(executionResult, parameters, state)
    }

}

[bbakerman]

This class shows as a hotspot for field instrumentation in particular.

Note the overhead of field instrumentation when using chained instrumentations, due to the frequency of beginField calls for any non-trivial query.

So in many ways this is expected. The profiling above shows

private InstrumentationState getState(Instrumentation instrumentation) {
            return instrumentationToStates.get(instrumentation);
}

which is a hashmap of states in the chain. A map look up should not be slow but it is being called often.

The same is true of beginField - if you query has lots of fields - the instrumentation is going to get a callback for each field.

You mention that you have a couple of instrumentations - what are they ?

Ideally they would directive from graphql.execution.instrumentation.SimplePerformantInstrumentation which is newish and a smidge more performant.

The optimization that @rrva has will be faster because its very specific. The graphql java code needs to be able to generically run any instrumentation. Where as @rrva runs specific bits of code that he is aware of - which is a faster way to run things but its not generic - its highly coupled to specific code

That said the next version of graphql-java is trying to reduce the default data loader instrumentation that always gets added. Instead if will be implemented in the engine itself. This MAY save some time but we havent yet done the perf tests for that.

[DanielThomas]

We have 6 instrumentations, more if a service adds application specific ones - so at least 6 getState calls for every field.

I've fixed this here:

#3459

[bbakerman]

Closing as fixed in v22