Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Introduce EventCounters overview article and tutorial doc #19635

Merged
merged 28 commits into from
Aug 7, 2020
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
28 commits
Select commit Hold shift + click to select a range
12e6b37
Initial bits of the EventCounter articles
IEvangelist Jul 22, 2020
b9895aa
Added event counter articles to TOC
IEvangelist Jul 22, 2020
b5aa379
Low hanging fruit from acrolinx
IEvangelist Jul 22, 2020
2618fee
Sweeping edit pass on overview, cleared about 40 issues
IEvangelist Jul 22, 2020
634a9ec
Pre-commit hook, applied automatic markdownlint CLI fixes
IEvangelist Jul 22, 2020
40d7a48
More updates
IEvangelist Jul 22, 2020
8d3d576
Compressed images, and minor tweaks
IEvangelist Jul 22, 2020
3f048af
Add next steps
IEvangelist Jul 23, 2020
9bdc324
Introduced code files under snippets, minor updates from review
IEvangelist Jul 31, 2020
3e56a0f
Apply suggestions from code review
IEvangelist Jul 27, 2020
46b87fb
Oops, updates from merge
IEvangelist Jul 31, 2020
250cbc4
Apply suggestions from code review
IEvangelist Jul 31, 2020
5ea2375
Minor updates, and added SVG
IEvangelist Jul 31, 2020
a261bbe
More working updates
IEvangelist Jul 31, 2020
1d60d51
fixed SVG image, added background color for dark theme
IEvangelist Jul 31, 2020
38bbfdf
More updates... still working to address all the feedback
IEvangelist Jul 31, 2020
f30fea0
Again updates, and new additions
IEvangelist Jul 31, 2020
4846be2
More tweaks
IEvangelist Jul 31, 2020
324e95c
Incremental updates
IEvangelist Aug 4, 2020
892f886
Fixed range
IEvangelist Aug 4, 2020
8b46613
Updates on the overview article
IEvangelist Aug 5, 2020
d8f791d
More updates, getting closer to finalizing the tutorial
IEvangelist Aug 5, 2020
5d75aee
removed bad merge
IEvangelist Aug 6, 2020
60c255e
Forcefully update ever-changing TOC from master
IEvangelist Aug 6, 2020
c514623
Make actions more conceptual for the overview
IEvangelist Aug 6, 2020
d0a9253
Apply suggestions from code review
IEvangelist Aug 7, 2020
42cb5a0
Updates
IEvangelist Aug 7, 2020
0d1ebda
Pre-commit hook, applied automatic markdownlint CLI fixes
IEvangelist Aug 7, 2020
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
47 changes: 34 additions & 13 deletions docs/core/diagnostics/dotnet-counters.md
Original file line number Diff line number Diff line change
Expand Up @@ -38,11 +38,11 @@ dotnet-counters [-h|--help] [--version] <command>
## Commands

| Command |
| --------------------------------------------------- |
|-----------------------------------------------------|
| [dotnet-counters collect](#dotnet-counters-collect) |
| [dotnet-counters list](#dotnet-counters-list) |
| [dotnet-counters monitor](#dotnet-counters-monitor) |
| [dotnet-counters ps](#dotnet-counters-ps) |
| [dotnet-counters ps](#dotnet-counters-ps) |

## dotnet-counters collect

Expand Down Expand Up @@ -101,18 +101,39 @@ dotnet-counters list [-h|--help]

```console
> dotnet-counters list

Showing well-known counters only. Specific processes may support additional counters.
System.Runtime
cpu-usage Amount of time the process has utilized the CPU (ms)
working-set Amount of working set used by the process (MB)
gc-heap-size Total heap size reported by the GC (MB)
gen-0-gc-count Number of Gen 0 GCs / sec
gen-1-gc-count Number of Gen 1 GCs / sec
gen-2-gc-count Number of Gen 2 GCs / sec
exception-count Number of Exceptions / sec
Showing well-known counters only. Specific processes may support additional counters.

System.Runtime
cpu-usage Amount of time the process has utilized the CPU (ms)
working-set Amount of working set used by the process (MB)
gc-heap-size Total heap size reported by the GC (MB)
gen-0-gc-count Number of Gen 0 GCs / min
gen-1-gc-count Number of Gen 1 GCs / min
gen-2-gc-count Number of Gen 2 GCs / min
time-in-gc % time in GC since the last GC
gen-0-size Gen 0 Heap Size
gen-1-size Gen 1 Heap Size
gen-2-size Gen 2 Heap Size
loh-size LOH Heap Size
alloc-rate Allocation Rate
assembly-count Number of Assemblies Loaded
exception-count Number of Exceptions / sec
threadpool-thread-count Number of ThreadPool Threads
monitor-lock-contention-count Monitor Lock Contention Count
threadpool-queue-length ThreadPool Work Items Queue Length
threadpool-completed-items-count ThreadPool Completed Work Items Count
active-timer-count Active Timers Count

Microsoft.AspNetCore.Hosting
requests-per-second Request rate
total-requests Total number of requests
current-requests Current number of requests
failed-requests Failed number of requests
```

> [!NOTE]
> The `Microsoft.AspNetCore.Hosting` counters are displayed when there are processes identified that support these counters, for example; when an ASP.NET Core application is running on the host machine.

## dotnet-counters monitor

Displays periodically refreshing values of selected counters.
Expand Down Expand Up @@ -166,7 +187,7 @@ dotnet-counters monitor [-h|--help] [-p|--process-id] [--refreshInterval] [count
GC Heap Size (MB) 811
```

- Monitor `EventCounter` values from user-defined `EventSource`. For more information, see [Tutorial: How to measure performance for very frequent events using EventCounters](https://github.com/dotnet/runtime/blob/master/src/libraries/System.Diagnostics.Tracing/documentation/EventCounterTutorial.md).
- Monitor `EventCounter` values from user-defined `EventSource`. For more information, see [Tutorial: Measure performance using EventCounters in .NET Core](event-counter-perf.md).

```console
> dotnet-counters monitor --process-id 1902 Samples-EventCounterDemos-Minimal
Expand Down
217 changes: 217 additions & 0 deletions docs/core/diagnostics/event-counter-perf.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,217 @@
---
title: Measure performance using EventCounters in .NET Core
description: In this tutorial, you'll learn how to measure performance using EventCounters.
ms.date: 08/07/2020
ms.topic: tutorial
---

# Tutorial: Measure performance using EventCounters in .NET Core
IEvangelist marked this conversation as resolved.
Show resolved Hide resolved

**This article applies to: ✔️** .NET Core 3.0 SDK and later versions

In this tutorial, you'll learn how an <xref:System.Diagnostics.Tracing.EventCounter> can be used to measure performance with a high frequency of events. You can use the [available counters](event-counters.md#available-counters) published by various official .NET Core packages, third-party providers, or create your own metrics for monitoring.

In this tutorial, you will:

> [!div class="checklist"]
>
> - Implement an <xref:System.Diagnostics.Tracing.EventSource>.
> - Monitor counters with [dotnet-counters](dotnet-counters.md).

## Prerequisites

The tutorial uses:

- [.NET Core 3.1 SDK](https://dotnet.microsoft.com/download/dotnet-core) or a later version.
- [dotnet-counters](dotnet-counters.md) to monitor event counters.
- A [sample debug target](https://docs.microsoft.com/samples/dotnet/samples/diagnostic-scenarios) app to diagnose.

## Get the source

The sample application will be used as a basis for monitoring. The [sample ASP.NET Core repository](https://docs.microsoft.com/samples/dotnet/samples/diagnostic-scenarios) is available from the samples browser. You download the zip file, extract it once downloaded, and open it in your favorite IDE. Build and run the application to ensure that it works properly, then stop the application.

## Implement an EventSource

For events that happen every few milliseconds, you'll want the overhead per event to be low (less than a millisecond). Otherwise, the impact on performance will be significant. Logging an event means you're going to write something to disk. If the disk is not fast enough, you will lose events. You need a solution other than logging the event itself.

When dealing with a large number of events, knowing the measure per event is not useful either. Most of the time all you need is just some statistics out of it. So you could get the statistics within the process itself and then write an event once in a while to report the statistics, that's what <xref:System.Diagnostics.Tracing.EventCounter> will do.

Below is an example of how to implement an <xref:System.Diagnostics.Tracing.EventSource?displayProperty=fullName>. Create a new file named *MinimalEventCounterSource.cs* and use the code snippet as its source:

:::code language="csharp" source="snippets/EventCounters/MinimalEventCounterSource.cs":::

The <xref:System.Diagnostics.Tracing.EventSource.WriteEvent%2A?displayProperty=nameWithType> line is the <xref:System.Diagnostics.Tracing.EventSource> part and is not part of <xref:System.Diagnostics.Tracing.EventCounter>, it was written to show that you can log a message together with the event counter.

## Add an action filter

The sample source code is an ASP.NET Core project. You can add an [action filter](/aspnet/core/mvc/controllers/filters#action-filters) globally that will log the total request time. Create a new file named *LogRequestTimeFilterAttribute.cs*, and use the following code:

```csharp
using System.Diagnostics;
using Microsoft.AspNetCore.Http.Extensions;
using Microsoft.AspNetCore.Mvc.Filters;

namespace DiagnosticScenarios
{
public class LogRequestTimeFilterAttribute : ActionFilterAttribute
{
readonly Stopwatch _stopwatch = new Stopwatch();

public override void OnActionExecuting(ActionExecutingContext context) => _stopwatch.Start();

public override void OnActionExecuted(ActionExecutedContext context)
{
_stopwatch.Stop();

MinimalEventCounterSource.Log.Request(
context.HttpContext.Request.GetDisplayUrl(), _stopwatch.ElapsedMilliseconds);
}
}
}
```

The action filter starts a <xref:System.Diagnostics.Stopwatch> as the request begins, and stops after it has completed, capturing the elapsed time. The total milliseconds is logged to the `MinimalEventCounterSource` singleton instance. In order for this filter to be applied, you need to add it to the filters collection. In the *Startup.cs* file, update the `ConfigureServices` method in include this filter.

```csharp
public void ConfigureServices(IServiceCollection services) =>
services.AddControllers(options => options.Filters.Add<LogRequestTimeFilterAttribute>())
.AddNewtonsoftJson();
```

## Monitor event counter

With the implementation on an <xref:System.Diagnostics.Tracing.EventSource> and the custom action filter, build and launch the application.
You logged the metric to the <xref:System.Diagnostics.Tracing.EventCounter>, but unless you access the statistics from of it, it is not useful. To get the statistics, you need to enable the <xref:System.Diagnostics.Tracing.EventCounter> by creating a timer that fires as frequently as you want the events, as well as a listener to capture the events. To do that, you can use [dotnet-counters](dotnet-counters.md).

Use the [dotnet-counters ps](dotnet-counters.md#dotnet-counters-ps) command to display a list of .NET processes that can be monitored.

```console
dotnet-counters ps
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This command won't show anything because the app isn't running -- the directions had us run and stop it.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also should clarify if you have to run it using dotnet run, otherwise if you run it with VS you don't get a dotnet process, you get iisexpress. In that case you'll need two command prompts open.

```

Using the process identifier from the output of the `dotnet-counters ps` command, you can start monitoring the event counter with the following `dotnet-counters monitor` command:

```console
dotnet-counters monitor --process-id 2196 Sample.EventCounter.Minimal Microsoft.AspNetCore.Hosting[total-requests,requests-per-second] System.Runtime[cpu-usage]
```

While the `dotnet-counters monitor` command is running, hold <kbd>F5</kbd> on the browser to start issuing continuous requests to the `https://localhost:5001/api/values` endpoint. After a few seconds stop by pressing <kbd>q</kbd>

```console
Press p to pause, r to resume, q to quit.
Status: Running

[Microsoft.AspNetCore.Hosting]
Request Rate / 1 sec 9
Total Requests 134
[System.Runtime]
CPU Usage (%) 13
[Sample.EventCounter.Minimal]
Request Processing Time (ms) 34.5
Comment on lines +108 to +110
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

FYI, I don't see these numbers ever going above zero.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do you have the console open monitoring it, and a browser open - that is constantly being refreshed?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yes. holding down f5 didn't cause repeating refreshes so I pressed the key as rapidly as I could. The other numbers reflected the activity but not these.

```

The `dotnet-counters monitor` command is great for active monitoring. However, you may want to collect these diagnostic metrics for post processing and analysis. For that, use the `dotnet-counters collect` command. The `collect` switch command is similar to the `monitor` command, but accepts a few additional parameters. You can specify the desired output file name and format. For a JSON file named *diagnostics.json* use the following command:

```console
dotnet-counters collect --process-id 2196 --format json -o diagnostics.json Sample.EventCounter.Minimal Microsoft.AspNetCore.Hosting[total-requests,requests-per-second] System.Runtime[cpu-usage]
```

Again, while the command is running, hold <kbd>F5</kbd> on the browser to start issuing continuous requests to the `https://localhost:5001/api/values` endpoint. After a few seconds stop by pressing <kbd>q</kbd>. The *diagnostics.json* file is written. The JSON file that is written is not indented, however; for readability it is indented here.

```json
IEvangelist marked this conversation as resolved.
Show resolved Hide resolved
{
"TargetProcess": "DiagnosticScenarios",
"StartTime": "8/5/2020 3:02:45 PM",
"Events": [
{
"timestamp": "2020-08-05 15:02:47Z",
"provider": "System.Runtime",
"name": "CPU Usage (%)",
"counterType": "Metric",
"value": 0
},
{
"timestamp": "2020-08-05 15:02:47Z",
"provider": "Microsoft.AspNetCore.Hosting",
"name": "Request Rate / 1 sec",
"counterType": "Rate",
"value": 0
},
{
"timestamp": "2020-08-05 15:02:47Z",
"provider": "Microsoft.AspNetCore.Hosting",
"name": "Total Requests",
"counterType": "Metric",
"value": 134
},
{
"timestamp": "2020-08-05 15:02:47Z",
"provider": "Sample.EventCounter.Minimal",
"name": "Request Processing Time (ms)",
"counterType": "Metric",
"value": 0
},
{
"timestamp": "2020-08-05 15:02:47Z",
"provider": "System.Runtime",
"name": "CPU Usage (%)",
"counterType": "Metric",
"value": 0
},
{
"timestamp": "2020-08-05 15:02:48Z",
"provider": "Microsoft.AspNetCore.Hosting",
"name": "Request Rate / 1 sec",
"counterType": "Rate",
"value": 0
},
{
"timestamp": "2020-08-05 15:02:48Z",
"provider": "Microsoft.AspNetCore.Hosting",
"name": "Total Requests",
"counterType": "Metric",
"value": 134
},
{
"timestamp": "2020-08-05 15:02:48Z",
"provider": "Sample.EventCounter.Minimal",
"name": "Request Processing Time (ms)",
"counterType": "Metric",
"value": 0
},
{
"timestamp": "2020-08-05 15:02:48Z",
"provider": "System.Runtime",
"name": "CPU Usage (%)",
"counterType": "Metric",
"value": 0
},
{
"timestamp": "2020-08-05 15:02:50Z",
"provider": "Microsoft.AspNetCore.Hosting",
"name": "Request Rate / 1 sec",
"counterType": "Rate",
"value": 0
},
{
"timestamp": "2020-08-05 15:02:50Z",
"provider": "Microsoft.AspNetCore.Hosting",
"name": "Total Requests",
"counterType": "Metric",
"value": 134
},
{
"timestamp": "2020-08-05 15:02:50Z",
"provider": "Sample.EventCounter.Minimal",
"name": "Request Processing Time (ms)",
"counterType": "Metric",
"value": 0
}
]
}
```

## Next steps

> [!div class="nextstepaction"]
> [EventCounters](event-counters.md)
Loading