HostingEventSource uses EtwSelfDescribingFormat instead EtwManifestFormat

[shirhatti]

HostingEventSource, HttpConnectionsEventSource, and ConcurrencyLimiterEventSource used the EtwSelfDescribingFormat instead of the EtwManifestFormat. Surprisingly KestrelEventSource does not not have the same issue.

It looks like this change was inadvertently introduced as part of a previous change when switching to a different EventSource ctor that changed the behavior.

I haven't profiled this, but I assume there should be some minimal overhead observed on every WriteEvent call when ETW is enabled. This doesn't impact EventPipe profiling scenarios.

To quote @josalem

Manifest mode generates the manifest on initialization by reflecting over the methods on the EventSource and writing an XML file into memory. That file is sent whenever someone requests it and when someone starts listening to that source. It's only generated once. Self-describing creates a per-event metadata every time you send an event and attempts to send it with the event. EventPipe works some magic to reduce the amount of data sent, but EventSource still attempts to generate it.

A simple fix would be

namespace Microsoft.AspNetCore.Hosting
{
    internal sealed class HostingEventSource : EventSource
    {
        // Used for testing
        internal HostingEventSource(string eventSourceName)
-            : base(eventSourceName)
+            : base(eventSourceName, EventSourceSettings.EtwManifestEventFormat)
        {
        }
    }
}

[ghost]

Thanks for contacting us.
We're moving this issue to the Next sprint planning milestone for future evaluation / consideration. We will evaluate the request when we are planning the work for the next milestone. To learn more about what to expect next and how this issue will be handled you can read more about our triage process here.

[BrennanConroy]

Done via #30629

[benaadams]

Should they be EtwSelfDescribingFormat anyway?

From dotnet/runtime#27621 (comment)

ManifestBuilder functionality is largely a back-compat artifact for correct interoperation with legacy win7 and win8 era ETW readers. For any new usage he recommends customers create EventSource with the Self describing events.

and dotnet/runtime#27621 (comment)

If you wish to use complex types (that is something besides primitives, strings and DateTime), then you need to use the EtwSelfDescribingFormat flag when creating the EventSouce. This is very easy. In your TestEventSource class simpy add

private TestEventSource() : base(EventSourceSettings.EtwSelfDescribingEventFormat) { }

Things should work from there. We recommend people do this in general. We would have made this the default, except is is a breaking change for people using EventSource in manifest based scenarios.

[shirhatti]

Should they be EtwSelfDescribingFormat anyway?

If I understood correctly, as long as we don't have non-primitives types emitted we should be okay.

Re-opening this issue to verify that is indeed what's happening

[benaadams]

Other than comments in dotnet/runtime#27621 (comment) saying EtwManifestEventFormat legacy win7 and win8 backcompat and EtwSelfDescribingEventFormat should have been the default

The docs do also suggest Self Describing is preferred? https://docs.microsoft.com/en-us/windows/win32/tracelogging/trace-logging-about

TraceLogging is the new Windows 10 event tracing for user-mode applications and kernel-mode drivers. TraceLogging is a format for self-describing Event Tracing for Windows (ETW). TraceLogging builds on Event Tracing for Windows (ETW) and provides a simplified way to instrument code.

TraceLogging offers the simplicity of Windows software trace preprocessor (WPP) with the added benefit of being able to include structured data with events, the capability of correlating events, and all without requiring a separate instrumentation manifest XML file. Events are self-describing which means that a binary containing the instrumentation manifest does not need to be registered on the system in order to use the Trace Data Helper (TDH) APIs to decode and show events.
...
TraceLogging builds upon ETW but introduces several important improvements:

• Tracing an event is as simple as an API call.
• Events are self-describing and do not require any additional binaries containing the compiled event manifest to interpret the event. All the metadata about the event is recorded in the event.
• Activities inside a single process can be easily expressed through start and stop events.
• TraceLogging is compatible with existing instrumentation support. The new ETW APIs continue to support the old providers. You can invest in the new ETW APIs for strategic scenarios while leaving your old instrumentation points as they are.
• TraceLogging offers the same event tracing API for Windows 10, Xbox One, and Windows 10 Mobile.
• TraceLogging APIs are accessible from C, C++, .NET, and Windows Runtime.

[benaadams]

Will open issue in dotnet/runtime

[benaadams]

Raised issue dotnet/runtime#49410

[shirhatti]

I should have mentioned my motivation for making the change in the first place was your linked investigation. Assuming we move manifest generation in to source generator., there's no startup penalty or penalty on every invocation of WriteEvent (with ETW, EventPipe is always self-describing anyways).

[benaadams]

Assuming we move manifest generation in to source generator.

Priority was dropped on it 😢 dotnet/runtime#43390 (comment)

[shirhatti]

Unfortunately, I'm aware (and the instigator😅). Manifest generation is still a possibility, but it's the serializer/de-serializer generation that definitely not happening

[benaadams]

A whole lot of startup going into generating EventSource manifests and Guids etc for a standardish ASP.NET Core app with ApplicationInsights, e.g. this is https://themesof.net/

Couldn't fit it all on one screen, here's the rest

[shirhatti]

Have you measured the per WriteEvent call overhead when ETW is enabled? If not, I'll probably profile something like this later tomorrow

using System.Diagnostics.Tracing;

for (var i = 0; i < 10000; i++)
{
    MyEventSource.Log.MyEvent();
}

internal class MyEventSource : EventSource
{
    public static readonly MyEventSource Log = new MyEventSource();
    // public MyEventSource() : base("MyEventSource", EventSourceSettings.EtwManifestEventFormat)
    public MyEventSource() : base("MyEventSource", EventSourceSettings.EtwSelfDescribingEventFormat)
    { }
    [Event(1, Level = EventLevel.LogAlways)]
    public void MyEvent()
    {
        WriteEvent(1);
    }
}

[shirhatti]

@cijothomas As an FYI, you might be interested in ApplicationInsights contribution to the Startup profile. Based on the outcome of this conversation, you might be interested in copying whatever we end up doing here

[benaadams]

For https://themesof.net/ looks like 27 EventSources are created on startup, most of them probably just to check .Log.IsEnabled() and get false back... 😅

[benaadams]

Have you measured the per WriteEvent call overhead when ETW is enabled?

No, would be interesting to see the difference

[ghost]

Thanks for contacting us.
We're moving this issue to the Next sprint planning milestone for future evaluation / consideration. Because it's not immediately obvious that this is a bug in our framework, we would like to keep this around to collect more feedback, which can later help us determine the impact of it. We will re-evaluate this issue, during our next planning meeting(s).
If we later determine, that the issue has no community involvement, or it's very rare and low-impact issue, we will close it - so that the team can focus on more important and high impact issues.
To learn more about what to expect next and how this issue will be handled you can read more about our triage process here.

[adityamandaleeka]

@shirhatti Can you please update the issue with current state and re-milestone as appropriate?

[shirhatti]

Unfortunately, this slipped through the cracks for 6.0. Given that the expectation is that in 7.0, we have source generators for manifest generation, it is highly unlikely that we'd want to revert this change.

As such, I'm closing this issue despite knowing there is small impact on process start time for 6.0