Tracing .NET Core applications

In this article, we’ll look at different ways of collecting and inspecting events from the .NET Core runtime and base class library (BCL).

EventListener

The EventListener class allows us to get events of the running application. Let’s learn how to use it with an example application. Our application performs an HTTP get and prints the length of the received response.

using var httpClient = new HttpClient();
string response = await httpClient.GetStringAsync("http://redhatloves.net/");
Console.WriteLine($"Received response with length {response.Length}");

The .NET Core base classes (like HttpClient) record events using the EventSource class. Each EventSource has a name. EventSources are created when we are using some functionality. To know what sources are available, we’ll create an EventListener and override OnEventSourceCreated.

sealed class EventSourceCreatedListener : EventListener
{
    protected override void OnEventSourceCreated(EventSource eventSource)
    {
        base.OnEventSourceCreated(eventSource);
        Console.WriteLine($"New event source: {eventSource.Name}");
    }
}

When we instantiate this class, the base constructor will call OnEventSourceCreated for all existing sources. When new sources are added (for example, when we first use HttpClient) OnEventSourceCreated will be called for them, too.

We add an instance to our application:

using var eventSourceListener = new EventSourceCreatedListener();
using var httpClient = new HttpClient();
...

When we run the application this is this output:

New event source: Microsoft-Windows-DotNETRuntime
New event source: System.Runtime
New event source: Microsoft-System-Net-Http
New event source: System.Diagnostics.Eventing.FrameworkEventSource
New event source: Microsoft-Diagnostics-DiagnosticSource
New event source: Microsoft-System-Net-Sockets
New event source: Microsoft-System-Net-NameResolution
New event source: System.Threading.Tasks.TplEventSource
New event source: System.Buffers.ArrayPoolEventSource
New event source: Microsoft-System-Net-Security
New event source: System.Collections.Concurrent.ConcurrentCollectionsEventSource

The Microsoft-Windows-DotNETRuntime and System.Runtime are present when we create the EventSourceCreatedListener. The other event sources are created when we use the HttpClient. There is an event source for HTTP (Microsoft-System-Net-Http), we also see an event source for the name resolution (Microsoft-System-Net-NameResolution), security (Microsoft-System-Net-Security) and sockets (Microsoft-System-Net-Sockets). Let’s print events from the HTTP source to Console with another listener.

We create an EventListener that prints events for a specific EventSource:

sealed class EventSourceListener : EventListener
{
    private readonly string _eventSourceName;
    private readonly StringBuilder _messageBuilder = new StringBuilder();

    public EventSourceListener(string name)
    {
        _eventSourceName = name;
    }

    protected override void OnEventSourceCreated(EventSource eventSource)
    {
        base.OnEventSourceCreated(eventSource);

        if (eventSource.Name == _eventSourceName)
        {
            EnableEvents(eventSource, EventLevel.LogAlways, EventKeywords.All);
        }
    }

    protected override void OnEventWritten(EventWrittenEventArgs eventData)
    {
        base.OnEventWritten(eventData);

        string message;
        lock (_messageBuilder)
        {
            _messageBuilder.Append("<- Event ");
            _messageBuilder.Append(eventData.EventSource.Name);
            _messageBuilder.Append(" - ");
            _messageBuilder.Append(eventData.EventName);
            _messageBuilder.Append(" : ");
            _messageBuilder.AppendJoin(',', eventData.Payload);
            _messageBuilder.AppendLine(" ->");
            message = _messageBuilder.ToString();
            _messageBuilder.Clear();
        }
        Console.WriteLine(message);
    }
}

In OnEventSourceCreated we enable the receiving of events for the specific source. We’re not filtering for a specific log level (EventLevel.LogAlways) or specific keywords (EventKeywords.All). In OnEventWritten we print the event to the Console.

Now we add an instance to our program for the Microsoft-System-Net-Http EventSource:

using var httpEventListener = new EventSourceListener("Microsoft-System-Net-Http");
...

When we run our program again we get a lot of events from the HTTP EventSource. For example, we see that our request gets redirected and we see information about the SSL negotiation.

…
Event Microsoft-System-Net-Http - HandlerMessage : 55530882,6044116,0,SendAsyncCore,Received response: StatusCode: 301, ReasonPhrase: 'Moved Permanently'
…
<- Event Microsoft-System-Net-Http - HandlerMessage : 16294043,41622463,0,TraceConnection,HttpConnection(HttpConnectionPool https://developers.redhat.com:443). SslProtocol:Tls12, NegotiatedApplicationProtocol:, NegotiatedCipherSuite:TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, CipherAlgorithm:Aes256, CipherStrength:256, HashAlgorithm:None, HashStrength:0, KeyExchangeAlgorithm:DiffieHellman, KeyExchangeStrength:0, LocalCertificate:, RemoteCertificate:[Subject]
  CN=openshift.redhat.com, O=Red Hat, L=Raleigh, S=North Carolina, C=US

[Issuer]
  CN=GeoTrust RSA CA 2018, OU=www.digicert.com, O=DigiCert Inc, C=US
…

The EventSource named Microsoft-Windows-DotNETRuntime provides events from the runtime like the Garbage Collector (GC), just in time compiler (JIT) and ThreadPool.

dotnet-trace

dotnet-trace is a new global tool with .NET Core 3.0. With dotnet-trace we can create a trace from a running application.

To install dotnet-trace run:

dotnet tool install --global dotnet-trace

A trace can be created with the following command:

dotnet trace collect -p <pid> [--buffersize 256] [-o <outputpath>] [--providers <providerlist>] [--profile <profilename>] [--format NetTrace]

We need to specify the <pid> of the program that we want to trace. Optionally, we can specify a buffer size (default: 256MB). The output path is the filename for the trace file. providers and profile allow us to specify the events we are interested in. A profile is a pre-defined number of providers. You can see the available profiles using the list-profiles subcommand:

$ dotnet trace list-profiles
cpu-sampling     - Useful for tracking CPU usage and general .NET runtime information. This is the default option if no profile or providers are specified.
gc-verbose       - Tracks GC collections and samples object allocations.
gc-collect       - Tracks GC collections only at very low overhead.

As indicated in the output, if you don’t specify providers and a profile, the cpu-samping profile is used by default.

Multiple providers can be specified using a comma to separate them. By default, events will be captured for any keyword and level verbose. We can change this by appending a :[<keyword_hex_nr>]:<loglevel_nr>] suffix to the provider name. The keyword_hex_nr may be omitted to indicate all keywords. For example, to trace the Microsoft-System-Net-Http EventSource at EventLevel.Informational, we can specify: --providers Microsoft-System-Net-Http::4. An asterisk may be used to trace all events (i.e. --providers '*').

Some providers can be configured with additional key-value pairs. These are added to the provider name :[key1=value1][;key2=value2]. When the EventSource has associated EventCounters, the report interval can be set using the EventCounterIntervalSec key.

The default format (nettrace) is meant for the Windows PerfView tool. If you are doing performance analysis, you can use the speedscope format which can be opened on any platform using the https://www.speedscope.app/ website, or offline using the npm speedscopeapp package. When you are logging in the speedscope format, the trace is first captured into the nettrace format and then converted into the speedscope format. This conversion can also be done on the command line using dotnet trace convert.

For example, this is how you can trace a .NET Core application named web for the default profile (cpu-sampling) and output a speedscope file.

$ dotnet trace collect -p $(pidof web) --format speedscope

Provider Name                           Keywords            Level               Enabled By
Microsoft-System-Net-Http               0xFFFFFFFFFFFFFFFF  Verbose(5)          --providers

Process        : /tmp/web/bin/Debug/netcoreapp3.0/web
Output File    : /tmp/trace/trace.nettrace

[00:00:00:08]   Recording trace 2.3301   (MB)
Press  or  to exit...

Trace completed.
Writing:        /tmp/trace/trace.speedscope.json
Conversion complete

As indicated by the tool, you can stop tracing using Ctrl+C or Enter. For more information about using speedscope, check out Adam Sitnick’s blog post.

EventPipe environment variables

dotnet-trace enables the trace output when an application is running. By using environment variables we can also enable tracing from the application start. This also allows us to trace a tree of processes.

The EventPipeConfig has the same format as the dotnet trace providers argument. The EventPipeOutputPath refers to a folder. This allows multiple processes to write a trace file by including the process pid in the filename. The EventPipe uses the nettrace format.

For example, to capture all events from a console application, we can run:

COMPlus_EnableEventPipe=1 COMPlus_EventPipeConfig=* dotnet console.dll

TraceEvent library

If you want to write tools that process these trace files, you can use the Microsoft.Diagnostics.Tracing.TraceEvent library. This library also allows us to read the nettrace files on Linux:

# add the package:
#      dotnet add package Microsoft.Diagnostics.Tracing.TraceEvent

using System;
using Microsoft.Diagnostics.Tracing;
using Microsoft.Diagnostics.Tracing.Etlx;
using Microsoft.Diagnostics.Tracing.Parsers;

namespace console
{
    class Program
    {

        static void Main(string[] args)
        {
            if (args.Length < 1)
            {
                Console.WriteLine("You must specify a nettrace file.");
                return;
            }

            using (var traceLog = new TraceLog(TraceLog.CreateFromEventPipeDataFile(args[0])))
            {
                var traceSource = traceLog.Events.GetSource();

                traceSource.AllEvents += delegate (TraceEvent data) {
                    Console.WriteLine("{0}", data);
                };

                traceSource.Process();

           }
        }
    }
}

Microsoft.Extensions.Logging

ASP.NET Core uses the Microsoft.Extensions.Logging package for logging. You can find more information about this in Logging in .NET Core and ASP.NET Core. Multiple sinks can be configured as Logging providers. The EventSource logger provider (which is included by default) allows to include the ASP.NET Core log output in the trace output. The EventSource section describes how to use the Microsoft-Extensions-Logging EventSource with dotnet-trace, and control the format, and log level of the individual loggers.

dotnet-counters

dotnet-counters is a new global tool with .NET Core 3.0. With dotnet-counters we can live monitor EventCounters of a running .NET Core application.
To install counters run:

dotnet tool install --global dotnet-counters

Monitoring can be performed with the following command.

dotnet-counters monitor -p <pid> [--refreshInterval <intervalSec>] [<counter_list>]

When no counter list is specified, a default set of .NET runtime counters are shown information about the GC, ThreadPool, lock contention, active timers, and exception count.

<counter_list> can be specified as a space separated list of provider_name[:counter_name]. When the <counter_name> is omitted, all counters of the provider are included.

Conclusion

In this article, you’ve learned how you can capture events from the .NET Core runtime and BCL using EventListener, dotnet-trace, and EventPipe environment variables. Using the LoggingEventSource we can including events from Microsoft.Extensions.Logging (like ASP.NET Core). To view and analyze these events you can use PerfView on windows, the cross-platform speedscope, or build your own cross-platform tools using Microsoft.Diagnostics.Tracing.TraceEvent. With dotnet-counters we can get a live view of EventCounters.