Instrumentation

Hot Chocolate allows us to create custom diagnostic event listeners, giving us the ability to hook into internal instrumentation events and further process them.

We can subscribe to these events and delegate them either to our logging provider or another tracing infrastructure. We are free to gather data only on one event or all of them, allowing us to craft tracing behavior that fits the need of our project.

Diagnostic events

Currently we can implement diagnostic event listeners for the following event types:

We will learn more about how we can create diagnostic event listeners for these event types in their respective sections.

After we have created a diagnostic event listener for any event type, we can register it by calling AddDiagnosticEventListener on the IRequestExecutorBuilder, specifying the newly created diagnostic event listener as the generic type parameter.

C#
public class Startup
{
public void ConfigureServices(IServiceCollection services)
{
services
.AddGraphQLServer()
.AddDiagnosticEventListener<MyExecutionEventListener>();
}
}

If we need to access services from within our event handlers, we can inject them using the constructor. Please note that injected services are effectively singleton, since the diagnostic event listener is only instantiated once.

C#
public class MyExecutionEventListener : ExecutionDiagnosticEventListener
{
private readonly ILogger<MyExecutionEventListener> _logger;
public MyExecutionEventListener(ILogger<MyExecutionEventListener> logger)
=> _logger = logger;
public override void RequestError(IRequestContext context,
Exception exception)
{
_logger.LogError(exception, "A request error occured!");
}
}

⚠️ Note: Diagnostic event handlers are executed synchronously as part of the GraphQL request. Long running operations inside of a diagnostic event handler will negatively impact the query performance. Expensive operations should only be enqueued from within the handler and processed by a background service.

Scopes

Most diagnostic event handlers have a return type of void, but some return an IDisposable. These are event handlers that enclose a specific operation, sort of like a scope. This scope is instantiated at the start of the operation and disposed at the end of the operation.

To create a scope we can simply create a class implementing IDisposable.

C#
public class MyExecutionEventListener : ExecutionDiagnosticEventListener
{
private readonly ILogger<MyExecutionEventListener> _logger;
public MyExecutionEventListener(ILogger<MyExecutionEventListener> logger)
=> _logger = logger;
// this is invoked at the start of the `ExecuteRequest` operation
public override IDisposable ExecuteRequest(IRequestContext context)
{
var start = DateTime.UtcNow;
return new RequestScope(start, _logger);
}
}
public class RequestScope : IDisposable
{
private readonly ILogger _logger;
private readonly DateTime _start;
public RequestScope(DateTime start, ILogger logger)
{
_start = start;
_logger = logger;
}
// this is invoked at the end of the `ExecuteRequest` operation
public void Dispose()
{
var end = DateTime.UtcNow;
var elapsed = end - _start;
_logger.LogInformation("Request finished after {Ticks} ticks",
elapsed.Ticks);
}
}

If we are not interested in the scope of a specific diagnostic event handler, we can simply return an EmptyScope.

C#
public override IDisposable ExecuteRequest(IRequestContext context)
{
_logger.LogInformation("Request execution started!");
return EmptyScope;
}

Execution Events

We can hook into execution events of the Hot Chocolate execution engine by creating a class inheriting from ExecutionDiagnosticEventListener.

C#
public class MyExecutionEventListener : ExecutionDiagnosticEventListener
{
public override IDisposable ExecuteRequest(IRequestContext context)
{
// Omitted code for brevity
}
}

The following methods can be overriden.

Method nameDescription
ExecuteRequestScope that encloses the entire GraphQL request execution. Also the first diagnostic event raised during a GraphQL request.
RequestErrorCalled if the GraphQL request produced an error. Called immediately before the scope of ExecuteRequest is disposed.
ExecuteSubscriptionScope that encloses the execution of a subscription query. Scope is created once a client subscribes and disposed once the subscription ends.
ParseDocumentScope that encloses the parsing of a document.
SyntaxErrorCalled if a document could not be parsed due to a syntax error.
ValidateDocumentScope that encloses the validation of a document.
ValidationErrorsCalled if errors occured during the validation of the document.
StartProcessingScope that encloses the scheduling of some work, e.g. invoking a DataLoader or starting execution tasks.
StopProcessingCalled if the execution engine has to wait for resolvers to complete or whenever the execution has completed.
RunTaskScope that encloses the execution of an execution task. A ResolverExecutionTask uses the ResolveFieldValue event instead.
TaskErrorCalled if an execution task produced an error.
ResolveFieldValueScope that encloses the execution of a specific field resolver. (*)
ResolverErrorCalled if a specific field resolver produces an error.
OnSubscriptionEventScope that encloses the computation of a subscription result, once the event stream has yielded a new payload.
SubscriptionEventResultCalled once the subscription result has been successfully computed.
SubscriptionEventErrorCalled if the computation of the subscription result produced an error.
SubscriptionTransportErrorCalled if a subscription result could not be delivered to a client due to a transport issue.
AddedDocumentToCacheCalled once a document has been added to DocumentCache.
RetrievedDocumentFromCacheCalled once a document has been retrieved from the DocumentCache.
AddedOperationToCacheCalled once an operation has been added to the OperationCache.
RetrievedOperationFromCacheCalled once an operation has been retrieved from the OperationCache.
RetrievedDocumentFromStorageCalled once a document has been retrieved from a persisted query storage.
ExecutorCreatedCalled once a request executor has been created. Executors are created once for a schema (includes stitched schemas) during the first request.
ExecutorEvictedCalled once a request executor is evicted. This can happen if the schema or the configuration of the executor changes.

(*): The ResolveFieldValue event is not invoked per default, as it would be too much overhead to execute the event for each resolver used within a query. We have to override the EnableResolveFieldValue property in order for the execution engine to start invoking the event handler.

C#
public class MyExecutionEventListener : ExecutionDiagnosticEventListener
{
public override bool EnableResolveFieldValue => true;
public override IDisposable ResolveFieldValue(IMiddlewareContext context)
{
// Omitted code for brevity
}
}

Caching

It's important to note that some diagnostic events are executed differently based on whether caching is involved or not.

The ParseDocument event for example is only executed once for the same document. For subsequent requests using the same document the document is no longer parsed, i.e. the diagnostic event is not invoked.

While the ValidateDocument event is raised for each request, it only makes sense to measure the first validation. For subsequent requests the validation result might have been cached, as indicated by the IRequestContext.IsCachedDocument property.

C#
public override IDisposable ValidateDocument(IRequestContext context)
{
if (!context.IsCachedDocument)
{
// only profile the validation if the result has not been cached
}
return EmptyScope;
}

DataLoader Events

We can hook into DataLoader events by creating a class inheriting from ExecutionDiagnosticEventListener.

C#
public class MyDataLoaderEventListener : DataLoaderDiagnosticEventListener
{
public override IDisposable ExecuteBatch<TKey>(IDataLoader dataLoader,
IReadOnlyList<TKey> keys)
{
// Omitted code for brevity
}
}

The following methods can be overriden.

Method nameDescription
ExecuteBatchScope that encloses a batch operation, i.e. the resolution of a specific set of keys.
BatchResultsCalled once a batch operation has been completed, i.e. all items for a specific set of keys have been resolved.
BatchErrorCalled if a batch operation has failed.
BatchItemErrorCalled for a specific item that contained an error within a batch operation.
ResolvedTaskFromCacheCalled once a task to resolve an item by its key has been added or retrieved from the TaskCache.

Apollo Tracing

Apollo Tracing is a performance tracing specification for GraphQL servers. It works by returning tracing information about the current request alongside the computed data. While it is not part of the GraphQL specification itself, there is a common agreement in the GraphQL community that it should be supported by all GraphQL servers.

Example

GraphQL
{
book(id: 1) {
name
author
}
}

The above request would result in the below response, if Apollo Tracing is enabled.

JSON
{
"data": {
"book": {
"name": "C# in Depth",
"author": "Jon Skeet"
}
},
"extensions": {
"tracing": {
"version": 1,
"startTime": "2021-09-25T15:31:41.6515774Z",
"endTime": "2021-09-25T15:31:43.1602255Z",
"duration": 1508648100,
"parsing": { "startOffset": 13335, "duration": 781 },
"validation": { "startOffset": 17012, "duration": 323681 },
"execution": {
"resolvers": [
{
"path": ["book"],
"parentType": "Query",
"fieldName": "book",
"returnType": "Book",
"startOffset": 587048,
"duration": 1004748344
},
{
"path": ["book", "author"],
"parentType": "Book",
"fieldName": "author",
"returnType": "String",
"startOffset": 1005854823,
"duration": 500265020
}
]
}
}
}
}

Enabling Apollo Tracing

Apollo Tracing needs to be expicitly enabled by caling AddApolloTracing on the IRequestExecutorBuilder.

C#
public class Startup
{
public void ConfigureServices(IServiceCollection services)
{
services
.AddGraphQLServer()
.AddApolloTracing();
}
}

Further we can specify a TracingPreference. Per default it is TracingPreference.OnDemand.

C#
services
.AddGraphQLServer()
.AddApolloTracing(TracingPreference.Always);

There are three possible options for the TracingPreference.

OptionDescription
NeverApollo Tracing is disabled. Useful if we want to conditionally disable Apollo Tracing.
OnDemandApollo Tracing only traces requests, if a specific header is passed with the query request.
AlwaysApollo Tracing is always enabled and all query requests are traced automatically.

On Demand

When Apollo Tracing is added using the TracingPreference.OnDemand, we are required to pass one of the following HTTP headers with our query request in order to enable tracing for this specific request.

  • GraphQL-Tracing=1
  • X-Apollo-Tracing=1

When using curl this could look like the following.

Bash
curl -X POST -H 'GraphQL-Tracing: 1' -H 'Content-Type: application/json' \
-d '{"query":"{\n book(id: 1) {\n name\n author\n }\n}\n"}' \
'http://localhost:5000/graphql'