Adding EventSource events to Hosting

[kichalla]

Events

• Host start/end
• Request start/end

@davidfowl @rynowak @shirhatti

[Tratcher]

Request start/end: https://github.com/aspnet/Hosting/blob/dev/src/Microsoft.AspNetCore.Hosting/Internal/HostingApplication.cs#L36

[cwe1ss]

Will you add additional EventSource instrumentation for Request start/end? I thought the guidance is to use DiagnosticSource since it has a bridge to EventSource anyway?!
Seems quite wasteful to manually instrument ILogger, DiagnosticSource and EventSource everywhere.

[rynowak]

Seems quite wasteful to manually instrument ILogger, DiagnosticSource and EventSource everywhere.

We're definitely not doing this everywhere 😆

We're adding these particular event source data because they provide value to us for performance work. We've added DiagnosticSource and Logging at other times because it provides value in those cases. Each of these systems is optimized for a few particular things

[cwe1ss]

DiagnosticSource is great - I'm using it in my upcoming OpenTracing instrumentation! I'm just wondering because the DiagnosticSource events seems to have the same information.
Is the DiagnosticSource->EventSource bridge on by default or does it require additional configuration/dependencies? (I haven't yet used it).

What do you see as use cases for EventSource vs DiagnosticSource vs. DiagnosticSource->EventSource bridge?

[rynowak]

Down at the bottom is a dump of my design notes from a conversation around logging/diagnostic source (back when it was TelemetrySource). I'd link it, but it's a private repo 😭

In terms of how we are using it, event source is for us, logging is for all of you, and diagnostic source is for partners. We intend to use event source with etw/dtrace/etc to do performance and reliability work. As such we're primarily interested in using it for things that we can write tooling around. We're starting with the most obvious things and will add more as we find cases where we need it.

I think of event source as very similar to logging in a few ways.

• The implementor decides what to log
• Has key-value pairs
• Events have a clear interpretation - they indicate a thing that happened

Event source can even include a human-readable message if you so desire.

In a way that's similar to logging, we will use event source to "bookend" things like a request start/stop to provide context.

---

Regarding DiagnosticSource, Lou and I took a walk and thought about what an dreamy technology would look like for a partner like Glimpse or MiniProfiler. Basically an event bus with proxy generation support. The event bus part made it into CoreFx and we ship the proxy part as a standalone.

There's more about it in the design notes, but basically we provide a lot of context and state in our DS notifications. The consumer decides what information is relevant and they collect it.

I haven't personally played with the ds -> es bridge. We're generally using DS to provide highly structured objects that aren't really suitable for use with something like ETW.

---

Warning Design Notes Dump

So we've got two diagnostics systems, Logging (ILogger), and Telemetry (TelemetrySource) née INotifier. This document will attempt to explain the motivations for having two systems and how and when to use each.

Comparison

Logging usually looks like:

logger.LogVerbose(
  "Skipped content negotiation as content type '{ContentType}' is explicitly set for the response.", 
  ContentTypes[0]);

Logging sometimes looks like:

using (_logger.BeginScope("ActionId: {ActionId}", actionDescriptor.Id))
{
  _logger.LogVerbose("Executing action {ActionDisplayName}", actionDescriptor.DisplayName);
  ...
}

Telemetry Source looks like:

if (_telemetry.IsEnabled("Microsoft.AspNet.Mvc.AfterAction"))
{
  _telemetry.WriteTelemetry(
    "Microsoft.AspNet.Mvc.AfterAction",
    new { actionDescriptor, httpContext = context.HttpContext });
}

So what's the difference?

There is a major difference of course in format.

Logging is always human-readable text, optionally with key-value pairs to support processing with tools. Telemetry is always complex objects, it would be rare to see a string sent to telemetry at all.

At its most bare-bones, logging is always something that could be used by a human pattern-matcher to interpret a serial set of events or solve a problem. Each event in a log has a clean meaning, it has to state a fact -- Action {DisplayName} was selected.

Telemetry data is often free of any interpretation or inherent meaning - if it were stating a fact it wouldn't be very insightful -- I am about to run an action. Often a telemetry event indicates a stage of application processing rather than a significant result of processing. The semantic meaning of a telemetry event is only added by an external tool proving analysis.

The usage of the data provider also differs.

Logging data, with key-value pairs is persisted either to a file, or a database of some kind. With a passing nod to filtering by verbosity... a logging sink is generally interested in all events rather than specific events.

Ultimately to use the logging data, an adminstrator is likely doing BI by performing queries over key-value data or troubleshooting by looking for a root cause of a failure in the event stream. In either case, the logging statements in code specify what data is available in a fixed set. A listener may choose to dial up or down the verbosity per-component, but the onus is always on the application developer to determine what events and data bear the most significance.

Telemetry data doesn't specify any format for persistance and isn't friendly to generalized storage and querying. Telemetry data is always used by tools, and those tools register interest in specific events that are meaningful for the type of analysis they provide.

For consuming telemetry data, the tool author is in control. A telemetry event provides all of the useful context data, and the tool interpreting it decides what pieces of the data are relevant for analysis.

A few general conclusions:

• Logging is optimized for lots of granular events with a clear interpretation.
• Telemetry is optimized for providing lots of context at key moments.
• Logging may include queryable data. You have to decide up front what text and data is significant.
• Telemetry includes all available context. Tools decide what parts are meaningful.
• Logging doesn't make a contract. Analysis isn't coupled to specific event defintions.
• Telemetry is a contract. Tools are coupled to specific event defitions.

Guidance

Use logging for significant results of framework processing - Ex: Selected ContentType {ContentType}

Use logging to provide context around user-code - Ex: creating a scope for the action in MVC

We decide what to log in the framework. We're responsible for determining what's useful for troubleshooting.

Use telemetry in significant stages of framework processing - Ex: before/after action in MVC

• This also serves to provide context around user code, but in this case we're enabling tools do that

It's not wrong to use telemetry to record a significant framework result - Ex: searching for a view in MVC

• Think about whether the event being defined could be generalized.
• Telemetry events form a contract so we want to be thoughtful about how many we create and how reusable they are

Telemetry events aren't useful without a partner signed up to build tooling. Don't eagerly add Telemetry without a significant and realistic tooling scenario commited.

[kichalla]

4abb48e