Skip to content

Commit

Permalink
Acrolinx 4/4 (dotnet#28910)
Browse files Browse the repository at this point in the history
  • Loading branch information
gewarren authored Apr 6, 2022
1 parent 0497ba6 commit 8bf3b4a
Show file tree
Hide file tree
Showing 6 changed files with 88 additions and 93 deletions.
42 changes: 21 additions & 21 deletions docs/core/diagnostics/eventsource-activity-ids.md
Original file line number Diff line number Diff line change
Expand Up @@ -9,21 +9,21 @@ ms.date: 03/24/2022
**This article applies to: ✔️** .NET Core 3.1 and later versions **✔️** .NET Framework 4.5 and later versions

This guide explains Activity IDs, an optional identifier that can be logged with each event generated using
<xref:System.Diagnostics.Tracing.EventSource?displayProperty=nameWithType>. For an introduction see
<xref:System.Diagnostics.Tracing.EventSource?displayProperty=nameWithType>. For an introduction, see
[Getting Started with EventSource](./eventsource-getting-started.md).

## The challenge of logging concurrent work

Long ago a typical application may have been simple and single-threaded which makes logging straightforward. You
Long ago, a typical application may have been simple and single-threaded, which makes logging straightforward. You
could write each step to a log file in order and then read the log back exactly in the order it was written to
understand what happened. If the app handled requests then only one request was handled at a time. All log
messages for request A would be printed in order, then all the messages for B, and so on.
When apps become multi-threaded that strategy no longer works because multiple
requests are being handled at the same time. However if each request is assigned to a single thread which processes
it entirely you can solve the problem by recording a thread id for each log message. For example a multi-threaded app
requests are being handled at the same time. However if each request is assigned to a single thread that processes
it entirely, you can solve the problem by recording a thread ID for each log message. For example, a multi-threaded app
might log:

```
```txt
Thread Id Message
--------- -------
12 BeginRequest A
Expand All @@ -33,10 +33,10 @@ Thread Id Message
190 Doing some work
```

By reading the thread ids you know that thread 12 was processing request A and thread 190 was processing request B,
By reading the thread IDs you know that thread 12 was processing request A and thread 190 was processing request B,
therefore the 'uh-oh error happened' message related to request A. However application concurrency has continued to
grow ever more sophisticated. It is now common to use `async` and `await` so that a single request could
be handled partially on many different threads before the work is complete. Thread ids are no longer sufficient to
grow ever more sophisticated. It's now common to use `async` and `await` so that a single request could
be handled partially on many different threads before the work is complete. Thread IDs are no longer sufficient to
correlate together all the messages produced for one request. Activity IDs solve this problem. They provide a finer
grain identifier that can track individual requests, or portions of requests, regardless of if the work
is spread across different threads.
Expand Down Expand Up @@ -154,23 +154,23 @@ TID Activity ID Event Arguments
Using the Activity IDs you can see that all of the messages for work item A have ID `00000011-...` and all the messages for
work item B have ID `00000012-...`. Both work items first did some work on thread 21256, but then each of them continued their work
on separate threadpool threads 11348 and 14728 so trying to track the request only with thread IDs would not have worked.
on separate threadpool threads 11348 and 14728 so trying to track the request only with thread IDs wouldn't have worked.

EventSource has an automatic heuristic where defining an event named _Something_Start followed immediately by another event named
_Something_Stop is considered the start and stop of a unit of work. Logging the start event for a new unit of work creates a new
Activity ID and begins logging all events on the same thread with that Activity ID until the stop event is logged. The ID also
automatically follows async control flow when using `async` and `await`. Although it is recommended to use the Start/Stop naming suffixes
automatically follows async control flow when using `async` and `await`. Although we recommend that you use the Start/Stop naming suffixes,
you may name the events anything you like by explicitly annotating them using the
<xref:System.Diagnostics.Tracing.EventAttribute.Opcode?displayProperty=nameWithType> property with the first event set to
EventOpcode.Start and the second set to EventOpcode.Stop.
<xref:System.Diagnostics.Tracing.EventAttribute.Opcode?displayProperty=nameWithType> property. Set the first event to
`EventOpcode.Start` and the second to `EventOpcode.Stop`.

## Log requests that do parallel work

Sometimes a single request might do different parts of its work in parallel and you both want to group all the log events
as well as the sub-parts. The example below simulates a request that does two database queries in parallel and then does some
Sometimes a single request might do different parts of its work in parallel, and you want to group all the log events
and the subparts. The example below simulates a request that does two database queries in parallel and then does some
processing on the result of each query. You want to isolate the work for each query, but also understand which queries belong
to the same request when many concurrent requests could be running. This is modeled as a tree where each top-level request is a root and
then sub-portions of work are branches. Each node in the tree gets its own Activity ID, and the first event logged with the new child
then subportions of work are branches. Each node in the tree gets its own Activity ID, and the first event logged with the new child
Activity ID logs an extra field called Related Activity ID to describe its parent.

Run the following code:
Expand Down Expand Up @@ -260,7 +260,7 @@ class ConsoleWriterEventListener : EventListener

This example prints output such as:

```
```txt
TID Activity ID Related Activity ID Event Arguments
34276 00000011-0000-0000-0000-000086af9d59 00000000-0000-0000-0000-000000000000 WorkStart A
34276 00001011-0000-0000-0000-0000869f9d59 00000011-0000-0000-0000-000086af9d59 QueryStart SELECT bowls
Expand All @@ -272,16 +272,16 @@ TID Activity ID Related Activity ID
32684 00000011-0000-0000-0000-000086af9d59 00000000-0000-0000-0000-000000000000 WorkStop
```

This example only ran one top level request which was assigned Activity ID `00000011-...`. Then each QueryStart event began
This example only ran one top-level request, which was assigned Activity ID `00000011-...`. Then each `QueryStart` event began
a new branch of the request with Activity IDs `00001011-...` and `00002011-...` respectively. You can identify these IDs are
children of the original request because both of the start events logged their parent `00000011-...` in the Related Activity ID field.

> [!NOTE]
> You may have noticed the numerical values of the IDs have some clear patterns between parent and child and are not random. Although it
> can assist in spotting the relationship visually in simple cases it is best for tools not to rely on this and treat the IDs as opaque identifiers.
> As the nesting level grows deeper the byte pattern will change. Using the Related Activity ID field is the best way to ensure tools
> You may have noticed the numerical values of the IDs have some clear patterns between parent and child and aren't random. Although it
> can assist in spotting the relationship visually in simple cases, it's best for tools not to rely on this and treat the IDs as opaque identifiers.
> As the nesting level grows deeper, the byte pattern will change. Using the Related Activity ID field is the best way to ensure tools
> work reliably regardless of nesting level.
Because requests with complex trees of sub-work items will generate many different Activity IDs these IDs are usually
Because requests with complex trees of subwork items will generate many different Activity IDs, these IDs are usually
best parsed by tools rather than trying to reconstruct the tree by hand. [PerfView](https://github.com/Microsoft/perfview) is one tool
that knows how to correlate events annotated with these IDs.
16 changes: 7 additions & 9 deletions docs/core/diagnostics/eventsource-collect-and-view-traces.md
Original file line number Diff line number Diff line change
Expand Up @@ -62,13 +62,11 @@ namespace EventSourceDemo
Most event collection tools use these configuration options to decide which events should be included in a trace:

- Provider names - This is a list of one or more EventSource names. Only events that are defined on EventSources
in this list are eligible to be included. To collect events from the DemoEventSource class in the example app
above you would need to include the EventSource name "Demo" in the list of provider names.
in this list are eligible to be included. To collect events from the DemoEventSource class in the preceding example app, you would need to include the EventSource name "Demo" in the list of provider names.
- Event verbosity level - For each provider you can define a verbosity level and events with
[verbosity](./eventsource-instrumentation.md#setting-event-verbosity-levels) higher than that level will be excluded
from the trace. If you specified that the "Demo" provider in the example app above should collect at the Informational
verbosity level then the DebugMessage event would be excluded because it has a higher level. Specifying
<xref:System.Diagnostics.Tracing.EventLevel> LogAlways(0) is a special case which indicates that events of any
from the trace. If you specified that the "Demo" provider in the preceding example app should collect at the Informational verbosity level, then the DebugMessage event would be excluded because it has a higher level. Specifying
<xref:System.Diagnostics.Tracing.EventLevel> LogAlways(0) is a special case that indicates that events of any
verbosity level should be included.
- Event keywords - For each provider you can define a set of keywords and only events tagged with at least one of
the keywords will be included. In the example app above if you specified the Startup keyword then only the
Expand All @@ -77,7 +75,7 @@ Most event collection tools use these configuration options to decide which even

### Conventions for describing provider configuration

Although each tool determines its own user interface for setting the trace configuration, there is a common convention
Although each tool determines its own user interface for setting the trace configuration, there's a common convention
many tools use when specifying the configuration as a text string. The list of providers is specified as a semi-colon
delimited list, and each provider element in the list consists of name, keywords, and level separated by colons. For example,
"Demo:3:5" identifies the EventSource named "Demo" with the keyword bitmask 3 (the `Startup` bit and the `Requests` bit) and
Expand Down Expand Up @@ -132,7 +130,7 @@ working with trace files in Visual Studio, see the
## PerfView

PerfView is a performance tool created by the .NET team that can collect and view ETW traces. It can also view trace files collected by other
tools in a variety of formats. In this tutorial, you'll collect an ETW trace of the [demo app](#example-app) and then examine the collected
tools in various formats. In this tutorial, you'll collect an ETW trace of the [demo app](#example-app) and then examine the collected
events in PerfView's event viewer.

### Collect a trace
Expand Down Expand Up @@ -184,7 +182,7 @@ To learn more about using PerfView, see the [PerfView video tutorials](https://d
## dotnet-trace

[dotnet-trace](./dotnet-trace.md) is a cross-platform command-line tool that can collect traces from .NET Core apps using
[EventPipe](./eventpipe.md) tracing. It does not support viewing trace data, but the traces it collects can be viewed by other tools such
[EventPipe](./eventpipe.md) tracing. It doesn't support viewing trace data, but the traces it collects can be viewed by other tools such
as [PerfView](#perfview) or [Visual Studio](#visual-studio). dotnet-trace also supports converting its default *.nettrace* format traces
into other formats, such as Chromium or [Speedscope](https://www.speedscope.app/).

Expand Down Expand Up @@ -217,7 +215,7 @@ into other formats, such as Chromium or [Speedscope](https://www.speedscope.app/
```

dotnet-trace uses the [conventional text format](#conventions-for-describing-provider-configuration) for describing provider configuration in
the --providers argument. For more options on how to take traces using dotnet-trace, see the
the `--providers` argument. For more options on how to take traces using dotnet-trace, see the
[dotnet-trace docs](./dotnet-trace.md#collect-a-trace-with-dotnet-trace).

## EventListener
Expand Down
32 changes: 16 additions & 16 deletions docs/core/diagnostics/eventsource-getting-started.md
Original file line number Diff line number Diff line change
Expand Up @@ -24,10 +24,10 @@ DemoEventSource.Log.AppStarted("Hello World!", 12);

This line of code has a logging object (`DemoEventSource.Log`), a method representing the event to log (`AppStarted`), and
optionally some strongly typed event parameters (`HelloWorld!` and `12`). There are no verbosity levels, event IDs, message
templates, or anything else that doesn't need to be at the callsite. All of this other information about events is written
templates, or anything else that doesn't need to be at the call site. All of this other information about events is written
by defining a new class derived from <xref:System.Diagnostics.Tracing.EventSource?displayProperty=nameWithType>.

Here is complete minimal example:
Here's a complete minimal example:

```C#
using System.Diagnostics.Tracing;
Expand All @@ -53,28 +53,28 @@ namespace EventSourceDemo
}
```

The DemoEventSource class declares a method for each type of event that you wish to log. In this case a single event called 'AppStarted' is defined
The DemoEventSource class declares a method for each type of event that you wish to log. In this case, a single event called 'AppStarted' is defined
by the AppStarted() method. Each time the code invokes the AppStarted method another AppStarted event will be recorded in the trace if the event is enabled.
This is some of the data that can be captured with each event:

- Event name - A name that identifies the kind of event which was logged. The event name will be identical to the method name, 'AppStarted' in this case.
- Event ID - A numerical id that identifies the kind of event which was logged. This serves a similar role to the name but can assist in fast automated
- Event name - A name that identifies the kind of event that was logged. The event name will be identical to the method name, 'AppStarted' in this case.
- Event ID - A numerical ID that identifies the kind of event that was logged. This serves a similar role to the name but can assist in fast automated
log processing. The AppStarted event has an ID of 1, specified in the <xref:System.Diagnostics.Tracing.EventAttribute>.
- Source name - The name of the EventSource which contains the event. This is used as a namespace for events. Event names and IDs only need to
- Source name - The name of the EventSource that contains the event. This is used as a namespace for events. Event names and IDs only need to
be unique within the scope of their source. Here the source is named "Demo", specified in the
<xref:System.Diagnostics.Tracing.EventSourceAttribute> on the class definition. The source name is also commonly refered to as a provider name.
<xref:System.Diagnostics.Tracing.EventSourceAttribute> on the class definition. The source name is also commonly referred to as a provider name.
- Arguments - All the method argument values are serialized.
- Other information - Events can also contain timestamps, thread IDs, processor IDs, [Activity IDs](./eventsource-activity-ids.md), stack traces, and event
metadata such as message templates, verbosity levels, and keywords.

For more information and best practices on creating events see [Instrumenting code to create events](./eventsource-instrumentation.md).
For more information and best practices on creating events, see [Instrumenting code to create events](./eventsource-instrumentation.md).

## Collect and view a trace file

There is no required configuration in code that describes which events should be enabled, where the logged data should be sent,
or what format the data should be stored in. If you run the app now it won't produce any trace file by default. EventSource uses the
[Publish-subscribe pattern](https://en.wikipedia.org/wiki/Publish%E2%80%93subscribe_pattern) which requires subscribers to indicate which events
should be enabled and to control all serialization for the subscribed events. EventSource has integrations for subscribing from
There's no required configuration in code that describes which events should be enabled, where the logged data should be sent,
or what format the data should be stored in. If you run the app now, it won't produce any trace file by default. EventSource uses the
[Publish-subscribe pattern](https://en.wikipedia.org/wiki/Publish%E2%80%93subscribe_pattern), which requires subscribers to indicate the events
that should be enabled and to control all serialization for the subscribed events. EventSource has integrations for subscribing from
[Event Tracing for Windows (ETW)](/windows/win32/etw/event-tracing-portal) and [EventPipe](./eventpipe.md) (.NET Core only).
Custom subscribers can also be created using the <xref:System.Diagnostics.Tracing.EventListener?displayProperty=nameWithType> API.

Expand Down Expand Up @@ -111,10 +111,10 @@ Opening the file in Visual Studio shows the events that were logged.

[![Visual Studio nettrace file](media/vs-nettrace-events.jpg)](media/vs-nettrace-events.jpg)

In the list view you can see the first event is the Demo/AppStarted event. The text column has the saved arguments, the timestamp column shows the event
occurred 27ms after logging started and to the right you can see the callstack. The other events are automatically enabled in every trace collected by
dotnet-trace though they can be ignored and filtered from view in the UI if they are distracting. Those extra events capture some information about the
process and jitted code which allows VS to reconstruct the event stack traces.
In the list view, you can see the first event is the Demo/AppStarted event. The text column has the saved arguments, the timestamp column shows the event
occurred 27 ms after logging started and to the right you can see the callstack. The other events are automatically enabled in every trace collected by
dotnet-trace though they can be ignored and filtered from view in the UI if they're distracting. Those extra events capture some information about the
process and jitted code, which allows Visual Studio to reconstruct the event stack traces.

## Learning more about EventSource

Expand Down
Loading

0 comments on commit 8bf3b4a

Please sign in to comment.