I'm attempting to add some response-time information to the logs of our Quarkus components so we can easily pinpoint slow requests and do general profiling based on log records.
However, this seems to be proving more difficult than anticipated.
Of note here is that we're using GraphQL, not REST. Most of the docs and code I've found seem oriented towards REST applications.
I cannot use the access-logs approach as the endpoint for graphql is just /graphql for all operations which doesn't give me any useful way to track down which operation was invoked.
My first thought was to simply output the opentelemetry span-id into the logs and I'd be able to trace it that way on a per-request basis.
Given that graphql allows multiple operations to be performed in one request, is there any known way to access timing information for each graphql operation being performed within the request in addition to top-level request response time?
And as a secondary question - how does one access the Span information in RouteFilters?
I tried adding a custom RouteFilter to output a log entry with the span trace-id and timing info when the request completed. That failed though as it seems the Span created during the request is not accessible in the lower request routing layers. Regardless of what I tried, I could only get the default "00000000" span trace-id.
eg:
public class MyRouteFilter
{
@RouteFilter(101)
void myFilter(RoutingContext rc) {
if (rc.normalizedPath().startsWith("/graphql")) {
long start=System.nanoTime();
rc.addBodyEndHandler(h -> {
double duration=(System.nanoTime() - start)/(double)1000000;
log.debug("response time: duration={}ms, traceId={}", duration, Span.current().getSpanContext().getTraceId());
});
}
rc.next();
}
}
With this, I get output like:
response time duration=5018.033293ms, traceId=00000000000000000000000000000000
This outputs the request duration properly, but without any context as to what request it was related to, it's not very useful.
