How to log latency for suspend function

[vgoyal200]

In am new in GraphQL and Kotlin, so pardon me in advance if I am not able to articulate my question well!

Assume:

type Classroom {
students: [Student!]!
capacity: int
name: String
}

type Student {
age: int!
name:String
}

Now, we have suspend function for each field to compute it.

class ClassroomQuery {private val classroom: Classroom
) : Query {
suspend fun classroom(
): Classroom =
classroom
}

class Classroom {
suspend fun capacity(): int = 40
suspend fun name(): String = bean
suspend fun students(): List {return listOf(Student)}
}

class Student {...}

As in graphql kotlin our classroomquery class not returns the actual response but the functions that will be invoked only when it is being called. So how can we log actual latency for classroomQuery class?

[samuelAndalon]

Hello, you can rely on Instrumentations to do this
https://www.graphql-java.com/documentation/instrumentation

specifically the beginFieldFetch and onDispatched, onCompleted

[vgoyal200]

will it be work with suspend function as well?

[samuelAndalon]

yes, the only async model compatible with graphql-java is CompletableFuture and we interop the suspendable fuctions to a future, so it should work

[samuelAndalon]

Example

@Component
class LogInstrumentation : Instrumentation {
    override fun beginFieldFetch(
        parameters: InstrumentationFieldFetchParameters,
        state: InstrumentationState?
    ): InstrumentationContext<Any>? {
        val start = System.currentTimeMillis();
        println("begin field fetch ${parameters.field.name}")
        return object : InstrumentationContext<Any> 
            override fun onDispatched(result: CompletableFuture<Any>?) {
            }
            override fun onCompleted(result: Any?, t: Throwable?) {
                val finish = System.currentTimeMillis();
                println("completed field fetch ${parameters.field.name}")
                println("elapsed time: ${finish - start}")
            }

        }
    }
}

GraphQL Koltin Server will automatically detect your instrumentation and apply it to the operations that you will execute

[vgoyal200]

Thanks, @samuelAndalon for the answers, but the problem is that I am not able to get the actual total time of fetching the root fields. Because all the fields compute asynchronously(suspend function), the time computing the root field does not include the time taken to compute each field.

So in my example, the total time taken to query Classroom does not include the time taken to compute students, name and capacity because they are processing asynchronously.

[samuelAndalon]

in that case i think you can use the beginExecutionStrategy and onDispatched, onCompleted

each time a complex object needs to be resolved a ExecutionStrategy starts, which will recursively start fetching all fields.

Take a look at that hook.

[dariuszkuc]

As @samuelAndalon mentioned you can use instrumentation for capturing this info (keep in mind there is some overhead for calculating this). Instead of custom instrumentation you could use graphql-java Apollo Tracing Instrumentation or Federated Tracing Instrumentation to calculate it for you.