How to see GraphQL specific metrics?

[IvBre]

Hello again,
Thank you for all of your hard work! ❤️

I was wondering how can one see any GraphQL specific metrics on the server? For example to be able to see a number of requests per query/mutation/subscription and per fields/params?
com.graphql-java-kickstart:graphql-spring-boot-starter has a possibility to expose these metrics via the actuator, but I can't find anything regarding metric collection in your docs.
These metrics should be then graphically exposed somewhere. Do you already have a tool that does that?
Something similar to what Apollo Studio offers would be ideal.

Thanks in advance!

[dariuszkuc]

Hello 👋
Similar to that graphql-java-kickstart project, we also rely on graphql-java for query execution logic. This means that you can utilize Instrumentation mechanism to "observe the execution of a query and also change the runtime behaviour".

e.g. graphql-java-kickstart project provides
https://github.com/graphql-java-kickstart/graphql-spring-boot/blob/master/graphql-spring-boot-autoconfigure/src/main/java/graphql/kickstart/autoconfigure/web/servlet/metrics/MetricsInstrumentation.java and you could create something similar in your repo. If you are using graphql-kotlin-spring-server then if you create instrumentation bean it will be automatically picked up by the autoconfiguration (https://opensource.expediagroup.com/graphql-kotlin/docs/server/spring-server/spring-beans/#graphql-configuration).

[IvBre]

Hello,

Thank you for your fast reply. I've recreated MetricsInstrumentation class like this:

@Component
class MetricsInstrumentation(
    private val meterRegistry: MeterRegistry,
    @Value("\${graphql.tracing.enabled}")
    private val tracingEnabled: Boolean = false
): TracingInstrumentation() {
    override fun instrumentExecutionResult(
        executionResult: ExecutionResult,
        parameters: InstrumentationExecutionParameters
    ): CompletableFuture<ExecutionResult>? {
        val tracingData = parameters
            .getInstrumentationState<TracingSupport>()
            .snapshotTracingData()

        if (tracingData != null && parameters.operation != "IntrospectionQuery") {
            val executionTimer: Timer = buildQueryTimer(parameters.operation, EXECUTION)
            executionTimer.record(tracingData[DURATION] as Long, TimeUnit.NANOSECONDS)

            // These next 2 ifs might not run if the document is cached on the document provider
            if (tracingData.containsKey(VALIDATION)
                && (tracingData[VALIDATION] as Map<String?, Any?>?)!!.containsKey(DURATION)
            ) {
                val validationTimer: Timer = buildQueryTimer(parameters.operation, VALIDATION)
                validationTimer.record(
                    (tracingData[VALIDATION] as Map<String?, Any?>?)!![DURATION] as Long,
                    TimeUnit.NANOSECONDS
                )
            }

            if (tracingData.containsKey(PARSING)
                && (tracingData[PARSING] as Map<String?, Any?>?)!!.containsKey(DURATION)
            ) {
                val parsingTimer: Timer = buildQueryTimer(parameters.operation, PARSING)
                parsingTimer.record(
                    (tracingData[PARSING] as Map<String?, Any?>?)!![DURATION] as Long,
                    TimeUnit.NANOSECONDS
                )
            }

            if ((tracingData[EXECUTION] as Map<String?, String?>?)!!.containsKey(RESOLVERS)) {
                ((tracingData[EXECUTION] as Map<String?, Any?>?)!![RESOLVERS] as List<Map<String?, Any?>>?)
                    ?.forEach { field: Map<String?, Any?> ->
                        val fieldTimer: Timer = buildFieldTimer(
                            parameters.operation,
                            field["parentType"] as String?,
                            field["fieldName"] as String?
                        )
                        fieldTimer.record(field[DURATION] as Long, TimeUnit.NANOSECONDS)
                    }
            }

            if (tracingEnabled) {
                executionResult.extensions[TRACING] = tracingData
            }
        }

        return CompletableFuture.completedFuture<ExecutionResult>(executionResult)
    }

    private fun buildQueryTimer(operationName: String?, operation: String): Timer =
        meterRegistry.timer(
            QUERY_TIME_METRIC_NAME,
            Tags.of(OPERATION_NAME_TAG, operationName ?: UNKNOWN_OPERATION_NAME)
                .plus(Tags.of(OPERATION, operation))

        )

    private fun buildFieldTimer(
        operationName: String?,
        parent: String?,
        field: String?
    ): Timer =
        meterRegistry.timer(
            RESOLVER_TIME_METRIC_NAME,
            Tags.of(OPERATION_NAME_TAG, operationName ?: UNKNOWN_OPERATION_NAME)
                .plus(Tags.of(PARENT, parent))
                .plus(Tags.of(FIELD, field))
                .plus(Tags.of(OPERATION, RESOLVERS))
        )

    companion object {
        private const val QUERY_TIME_METRIC_NAME = "graphql.timer.query"
        private const val RESOLVER_TIME_METRIC_NAME = "graphql.timer.resolver"
        private const val OPERATION_NAME_TAG = "operationName"
        private const val OPERATION = "operation"
        private const val UNKNOWN_OPERATION_NAME = "unknown"
        private const val PARENT = "parent"
        private const val FIELD = "field"
        private const val TRACING = "tracing"
        private const val DURATION = "duration"
        private const val EXECUTION = "execution"
        private const val VALIDATION = "validation"
        private const val PARSING = "parsing"
        private const val RESOLVERS = "resolvers"
    }
}

And indeed for fields, I'm getting actuator metrics. But for the query execution time (metric: QUERY_TIME_METRIC_NAME) the parameters.operation field is always empty so the metric can not tell me which operation the times recorded are for.
Here is what I'm getting in the actuator:

graphql_timer_query_seconds_count{operation="execution",operationName="unknown",} 1.0
graphql_timer_query_seconds_sum{operation="execution",operationName="unknown",} 1.716153523
graphql_timer_query_seconds_count{operation="parsing",operationName="unknown",} 1.0
graphql_timer_query_seconds_sum{operation="parsing",operationName="unknown",} 0.116560441
graphql_timer_query_seconds_count{operation="validation",operationName="unknown",} 1.0
graphql_timer_query_seconds_sum{operation="validation",operationName="unknown",} 0.025104855

I have a feeling the operation name is not set somewhere in the request flow, but not sure where to look. Do you have an idea?

[smyrick]

The operation name is set by the client request so it will be up to them to update their GraphQL files

No operation

{
  hello
}

No operation

query {
  hello
}

Operation name

query MyCustomHelloQuery {
  hello
}

[IvBre]

Ahh I see, then all is good. Thanks a lot!