Diagnostics: Low memory, cross platform .Net Core library for processing diagnostic & trace information

[MedAnd]

The Windows and Office 365 Security teams have implemented native Windows ETW libraries & managed .Net wrappers, given the existing .Net managed libraries and approaches suffer from various issues. From the Hidden Treasure: Intrusion Detection with ETW (Part 2) article:

The TDH APIs are what all ETW APIs ultimately call. While they offer a great deal of power, they’re still Win32-style APIs that are cumbersome to use. TraceEvent is a library used by the PerfView tool and has the benefits of being a well-designed .NET API. Unfortunately, it doesn’t perform well for scenarios where we want to keep memory usage to a minimum. System.Diagnostics.Tracing has the advantage of being part of the .NET BCL but we’ve observed intermittent exceptions and unexpected behavior in the past. Additionally, it suffers from the same memory consumption issue that TraceEvent does.

In response to these challenges, Office 365 Security chose to implement our own API with three primary goals:

Intuitive and flexible API
High performance – filtering events in the native layer
Available both in .NET and native C++

Having checked with both teams this week, neither team requires a High performance, low memory, cross platform .Net Core library for processing diagnostic & trace information. As such, this request is to discuss creating such a library or to optimize the existing ones, possibly taking the great work these teams have already done and applying to cross platform and .Net Core scenarios.

Moreover, the scope of this request encompasses all diagnostic & trace information, for example this library should be able to process real-time ETW traces on Windows, EventCounter on Windows / Linux etc.

Have linked to Tracing and Counters Interest Group - Announcements

[noahfalk]

I would start any performance related effort by defining what the goals are in terms of concrete benchmarks and desired numerical results. "High performance" to one person can be "horrible performance" to another. I don't know what goal the Office folks set out to achieve or how they were using the API to get their measurements. A quick experiment below shows TraceEvent on my dev machine reading a 3.4GB trace file containing 28 million events, then picking out, parsing, textually-formating and outputing an arbitrary subset of 575k events. It does this 4.27 seconds using 11MB more VM than a C# hello world app.

My best guess is that for most scenarios our .NET developers care about, TraceEvent can already satisfy their goals. However if the level of performance is insufficient it would be important to understand what result would be good enough and what scenarios are motivating us to achieve it.

Experiment code and results:

        string etwFile = @"C:\Users\noahfalk\Desktop\ManagedLangs-ReferenceSet-Iteration-1.etl\ReferenceSet4.etl";
        int numEvents = 0;
        int numParsedEvents = 0;
        Stopwatch sw = new Stopwatch();
        sw.Start();
        Console.WriteLine("Starting " + DateTime.Now);

        using (ETWTraceEventSource source = new ETWTraceEventSource(etwFile))
        using (FileStream output = File.OpenWrite(@"E:\out.txt"))
        {
            TextWriter writer = new StreamWriter(output);
            source.AllEvents += e =>
            {
                numEvents++;
            };
            source.Clr.All += e =>
            {
                numParsedEvents++;
                writer.WriteLine(e.ToString());
            };
            source.Process();
        }

        sw.Stop();
        Console.WriteLine("Elapsed time:                  " + sw.Elapsed);
        Console.WriteLine("Total Events processed:        " + numEvents);
        Console.WriteLine("Events Parsed and Reformatted: " + numParsedEvents);
        Console.ReadLine();

The result is:

Starting 7/3/2019 4:01:12 PM
Elapsed time:                  00:00:04.2733521
Total Events processed:        28742309
Events Parsed and Reformatted: 575621

The run consumed ~20MB of VM relative to ~9MB of VM for a .NET hello world app and produced a 146MB output file of formatted event text.

[MedAnd]

Happy to remove the High performance part of the tile 🙂 but to clarify my use case; which is to consume ETW events in real-time without writing to ETL files, including the new EventCounter design.

I would like to monitor in real-time all Service Fabric providers, the new EventCounter provider (roadmap?) etc and filter on specific level / typeId of events. For example warning and errors for some providers and information for other providers.

Given the number of providers, multiplied by the volume of events, from the Office 365 team's experience the existing managed libraries exhibit memory consumption issues, intermittent exceptions and unexpected behavior.

[noahfalk]

Happy to remove the High performance part of the tile 🙂 but to clarify my use case; which is to consume ETW events in real-time without writing to ETL files, including the new EventCounter design.

Its not clear which of the goals you suspect haven't already been met : )

High performance - It sounds like you were satisfied on that one
Low memory - This is also a performance measure so it would be good to clarify what memory usage amount you have in mind if the current performance wasn't good enough
cross platform - TraceEvent is already cross platform (ETW isn't, but we've created EventPipe to serve as a xplat replacement option)
real-time - TraceEvent already supports real-time operation. If you are using EventPipe, EventPipeEventSource has a constructor which takes a stream for real-time parsing. If you are using ETW ETWTraceEventSource has a constructor that takes a real-time session name.

from the Office 365 team's experience the existing managed libraries exhibit memory consumption issues, intermittent exceptions and unexpected behavior.

We are happy to get bug reports or requests for improvements, but we'd need to clarify what specific behavior is at issue (repro steps/observed result/actual result) before there is anything we can act on. I don't have any past knowledge of what the Office team tried to do or what they observed (my team didn't own that part of product at that point in time)

[MedAnd]

My assumption could have caused confusion and apologies. I think I understand and let me try explain why this request, more about my specific scenario below:

I am starting to develop a new microservice to process diagnostic & trace information at scale and large volume. I am initially developing on Windows and hosting within a Service Fabric Windows cluster. I want to also test running on a Service Fabric Linux cluster, this is on my client's medium term road-map, to host on Linux clusters.

Given the above, ideally I would use for the microservice .Net Core, future proof & battle tested .Net Core libraries. I have investigated to the best of my ability current options & existing documentation & found that my scenario sounds very similar to the Office 365 team's use case. Moreover I have gone through the history of numerous github issues relating to the current managed libraries as I want to make sure they are up to snuff, processing events in real-time from multiple (dozen or more ETW providers) with low memory use.

I'm happy to use TraceEvent if the issues identified in the article have been resolved (the article is from 2017)?

Any info on the maximum number of providers, filters, events and memory consumption tested would also be helpful to officially document?

These issues are my specific concern:

TraceEvent is a library used by the PerfView tool and has the benefits of being a well-designed .NET API. Unfortunately, it doesn’t perform well for scenarios where we want to keep memory usage to a minimum. System.Diagnostics.Tracing has the advantage of being part of the .NET BCL but we’ve observed intermittent exceptions and unexpected behavior in the past. Additionally, it suffers from the same memory consumption issue that TraceEvent does.

[noahfalk]

No worries @MedAnd! Doing this kind of clarifying discussion happens all the time, its just a natural part of working through the process.

I'm happy to use TraceEvent if the issues identified in the article have been resolved (the article is from 2017)?

My challenge is that the article wasn't specific about the issues. I can try to find the person who wrote the article or someone who was working on the technology 2 years ago who might remember a discussion, but so far I know as much about the issue as you do : )

Any info on the maximum number of providers, filters, events and memory consumption tested would also be helpful to officially document?

To the best of my knowledge TraceEvent streaming throughput is O(1) with respect to providers and event id based filtering and O(N) with respect to number of events. Memory usage would be reverse O(N) for providers/filters and O(1) event counts. I am not aware of any specific limits other than implicit ones based on available memory, CPU and IO speed on your hardware of choice. @brianrob might know of some past performance experiments (but he is on vacation right now). Typically I find the easiest and most reliable course of action is to make your own load test. By defining your own EventSources and events you could quickly build a load generator that will emit millions of events per second and then you can put any candidate technology to the test.

[MedAnd]

Was hoping phoning a friend would save me the work 🙂 but given above is not 100% definite and as you say; best I compare TraceEvent vs Office 365 Security library.... I'm happy to share back the findings if I can get assistance around using TraceEvent for my scenario?

So my scenario will be as per above, I want to start off by processing events in real-time from a known list of Service Fabric trace providers. Service Fabric emits a massive volume of trace data so this part should be fine.

The bit I could use guidance/direction/samples/documentation on is using TraceEvent in real-time to process 15-20 providers. I'll need to filter traces on specific event ids and trace levels. I will then want to forward on each relevant trace to a logger such as Serilog.

Would your team consider adding my scenario to the extensive & impressive suite of performance tests you already run for .Net Core... it would be great to have TraceEvent running in your CI&CD pipeline testing & reporting on processing of say 50 high volume providers in real-time (with advanced filtering)?

[noahfalk]

The bit I could use guidance/direction/samples/documentation on is using TraceEvent in real-time to process 15-20 providers.

I'd recommend good starting material:
Docs - https://github.com/microsoft/dotnet-samples/blob/master/Microsoft.Diagnostics.Tracing/TraceEvent/docs/TraceEvent.md
Samples - https://blogs.msdn.microsoft.com/vancem/2014/03/15/walk-through-getting-started-with-etw-traceevent-nuget-samples-package/
The first example is a heavily commented demo showing emitting and parsing ETW events using a real-time session. Starting from there you can modify it to add more providers and higher event sending volume as desired.

Would your team consider adding my scenario to the extensive & impressive suite of performance tests you already run for .Net Core

I'll leave that up to @brianrob who is the current maintainer of the TraceEvent library and our general .NET performance guru : )

[MedAnd]

Great to see this is scheduled for the 5.0 milestone!

[noahfalk]

I may be raining on the parade, but the milestone is often more of a guess or a 'we should consider this' rather than a schedule you can count on.

[MedAnd]

All good... nice to see this has not been forgotten!

[noahfalk]

I opened https://github.com/microsoft/perfview/issues/1042 to track the outstanding request for performance benchmarking and I responded above with a variety of doc and sample links on the documentation request. @MedAnd could you let me know if everything has been covered before I close this issue? Thanks!

[MedAnd]

Hi @noahfalk, just following up on this request; mainly for a scenario not previously documented at the time of this request.

Most documentation and perf testing around this area was for volume of TraceEvents one can load or save for just one trace provider. I'm hoping you can add samples/documentation on using TraceEvent in real-time to process 15-20+ different providers. For example filtering traces on specific event ids and trace levels which would then be forwarded to a logger such as Serilog.