Hot Chocolatev13

Instrumentation

Hot Chocolate allows us to create custom diagnostic event listeners, tapping into internal instrumentation events and further processing them. This abstraction allows us to use the logging or tracing infrastructure that we want to use. Further, we provide a default implementation for open telemetry.

Diagnostic events

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

We will learn more about creating diagnostic event listeners for these event types in their respective sections.

After creating a diagnostic event listener for any event type, we can register it by calling AddDiagnosticEventListener on the IRequestExecutorBuilder, specifying the newly developed 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 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 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 occurred!");
}
}
Warning

Diagnostic event handlers are executed synchronously as part of the GraphQL request. Long-running operations inside 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 event handlers enclose a specific operation, sort of like a scope. This scope is instantiated at the start of the operation and disposed of at the end of the operation.

We can simply create a class implementing IDisposable to create a scope.

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 return an EmptyScope. Returning an empty scope where we do not need to track a span will reduce the performance impact of triggering your event.

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

Server Events

We can instrument server events of the Hot Chocolate transport layer by creating a class inheriting from ServerDiagnosticEventListener.

C#
public class MyServerEventListener : ServerDiagnosticEventListener
{
public override IDisposable ExecuteHttpRequest(IRequestContext context)
{
// Omitted code for brevity
}
}
Method nameDescription
ExecuteHttpRequestCalled when starting to execute a GraphQL over HTTP request in the transport layer.
StartSingleRequestCalled within the ExecuteHttpRequest scope and signals that a single GraphQL request will be executed.
StartBatchRequestCalled within the ExecuteHttpRequest scope and signals that a GraphQL batch request will be executed.
StartOperationBatchRequestCalled within the ExecuteHttpRequest scope and signals that a GraphQL batch request will be executed.
HttpRequestErrorCalled within the ExecuteHttpRequest scope and signals that a error occurred while processing the GraphQL over HTTP request.
ParseHttpRequestCalled when starting to parse a GraphQL HTTP request.
ParserErrorsCalled within the ParseHttpRequest scope and signals that a error occurred while parsing the GraphQL request.
FormatHttpResponseCalled when starting to format a GraphQL query result.
WebSocketSessionCalled when starting to establish a GraphQL WebSocket session.
WebSocketSessionErrorCalled within the WebSocketSession scope and signals that a error occurred that terminated the session.

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 overridden.

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 occurred during the validation of the document.
AnalyzeOperationComplexityCalled when starting to analyze the operation complexity.
OperationComplexityAnalyzerCompiledCalled within AnalyzeOperationComplexity scope and reports that an analyzer was compiled.
OperationComplexityResultCalled within AnalyzeOperationComplexity scope and reports the outcome of the analyzer.
CoerceVariablesCalled when starting to coerce variables for a request.
CompileOperationCalled when starting to compile the GraphQL operation from the syntax tree.
ExecuteOperationCalled when starting to execute the GraphQL operation and its resolvers.
ExecuteStreamCalled within the execute operation scope if the result is a streamed result.
ExecuteDeferredTaskCalled when starting to execute a deferred part an operation within the ExecuteStream scope or within the ExecuteSubscription scope.
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 for the execution engine to invoke the event handler.

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

DataLoader Events

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

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

The following methods can be overridden.

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.

OpenTelemetry

OpenTelemetry is an open-source project and unified standard for service instrumentation or a way of measuring performance. Sponsored by the Cloud Native Computing Foundation (CNCF), it replaces OpenTracing and OpenCensus. The goal is to standardize how you collect and send telemetry data to a backend platform.

Hot Chocolate has implemented an OpenTelemetry integration, and you can easily opt into it instead of building a custom tracing integration.

Setup

To get started, add the HotChocolate.Diagnostics package to your project.

Bash
dotnet add package HotChocolate.Diagnostics
Warning
All HotChocolate.* packages need to have the same version.

Next, head over to your Program.cs and add AddInstrumentation to your GraphQL configuration.

C#
builder.Services
.AddGraphQLServer()
.AddQueryType<Query>()
.AddInstrumentation();

Now, we need to add OpenTelemetry to our project, and in the example here, we will use it with a Jaeger exporter.

Let's first add the needed packages:

Bash
dotnet add package OpenTelemetry.Extensions.Hosting --version 1.0.0-rc8
dotnet add package OpenTelemetry.Instrumentation.AspNetCore --version 1.0.0-rc8
dotnet add package OpenTelemetry.Instrumentation.Http --version 1.0.0-rc8
dotnet add package OpenTelemetry.Exporter.Jaeger --version 1.1.0

Now add the OpenTelemetry setup code to the Program.cs:

C#
builder.Logging.AddOpenTelemetry(
b =>
{
b.IncludeFormattedMessage = true;
b.IncludeScopes = true;
b.ParseStateValues = true;
b.SetResourceBuilder(ResourceBuilder.CreateDefault().AddService("Demo"));
});
builder.Services
.AddOpenTelemetryTracing()
.WithTracing(
b =>
{
b.AddHttpClientInstrumentation();
b.AddAspNetCoreInstrumentation();
b.AddHotChocolateInstrumentation();
b.AddJaegerExporter();
});

AddHotChocolateInstrumentation will register the Hot Chocolate instrumentation events with OpenTelemetry.

Your Program.cs should look like the following:

C#
using OpenTelemetry.Resources;
using OpenTelemetry.Trace;
var builder = WebApplication.CreateBuilder(args);
builder.Services
.AddGraphQLServer()
.AddQueryType<Query>()
.AddInstrumentation();
builder.Logging.AddOpenTelemetry(
b => b.SetResourceBuilder(ResourceBuilder.CreateDefault().AddService("Demo")));
builder.Services
.AddOpenTelemetryTracing()
.WithTracing(
b =>
{
b.AddHttpClientInstrumentation();
b.AddAspNetCoreInstrumentation();
b.AddHotChocolateInstrumentation();
b.AddJaegerExporter();
});
var app = builder.Build();
app.MapGraphQL();
app.Run();

When running GraphQL requests, you can now inspect in Jaeger how the request performed and look into the various parts of the execution telemetry.

Jaeger

Options

By default, we have not instrumented all of our execution events. You can drill deeper into the execution telemetry by adding more instrumentation scopes.

C#
builder.Services
.AddGraphQLServer()
.AddQueryType<Query>()
.AddInstrumentation(o =>
{
o.Scopes = ActivityScopes.All;
});

Beware, adding more instrumentation scopes is not free and will add more performance overhead.

Jaeger

Further, if you work with elastic and you want to give your root activity a name that is associated with the executed operation, you can quickly just tell the instrumentation to do just that for you.

C#
builder.Services
.AddGraphQLServer()
.AddQueryType<Query>()
.AddInstrumentation(o =>
{
o.RenameRootActivity = true;
});

Jaeger

Enriching Activities

You can inherit from ActivityEnricher and override the enrich method for an Activity to add custom data or remove default data.

C#
public class CustomActivityEnricher : ActivityEnricher
{
public CustomActivityEnricher(
ObjectPool<StringBuilder> stringBuilderPoolPool,
InstrumentationOptions options)
: base(stringBuilderPoolPool, options)
{
}
public override void EnrichResolveFieldValue(IMiddlewareContext context, Activity activity)
{
base.EnrichResolveFieldValue(context, activity);
activity.SetTag("custom", "data");
}
}

Register the custom activity enricher as a singleton:

C#
builder.Services.AddSingleton<ActivityEnricher, CustomActivityEnricher>();

Jaeger

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 all GraphQL servers should support it.

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 explicitly enabled by calling 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'