Rich Payload Data in EventSource V4.6.

  • [アーティクル]

In a previous blog I talked about the first of three interesting features of the new Version of V4.6 .NET EventSource, naming Activity tracking.

In this blog I would like to talk about one of the other two: EventSoruce Rich Data Payloads.

Note that .unlike the Activity support, this feature is fully available in the EventSource Nuget package, however, as always, we strongly encourage people to use the System.Diagnostics.Tracing.EventSource class built into the .NET framework if they can.   If can upgrade to V4.6 you can do this. 

 What are Rich Data Payloads?

As a review EventSource was predicated on the notion that you could pass TYPED payloads to your events for example

      void RequestStart(string url, int size) { WriteEvent(1, url, size); }

Defines a new event 'RequestStart' with a data payload that consists of two data items, the first is a string called 'url' and the second is an integer called 'size'.   EventSource keeps these track of these data item names and types so that processors (either EventListeners or ETW), can access both the data items names and types.   This makes mechanical processing of the event data easier. 

However before Version 4.6, the data items that could be passed were limited, to strings, primitive types, and a handful of special types (e.g. Guid and DateTime).   Now this set of data types covers ALOT ground (probably 95%+ or more of all items), however there are some times where being able to pass arrays (lists) of things are handy.   This is what Rich Data payloads gets you.   Thus there is no new API surface area with this feature, it is just that more things work than did before.   For example before the following EventSource definition would not have worked

      void LogInts(string name, int[] values) { WriteEvent(2, name, values); }

Because 'values' is not of the very few data types that are allowed (e.g. primitives and strings).  With rich data payloads, this call is now allowed. 

Rich Data does NOT mean 'Any Data'

A VERY IMPORTANT point however, is that RIch data does not mean 'anything'.   In almost all uses of EventSource the data you send will find its way OUTSIDE the process that created it.   It will either go to ETW, or to an EventListener that will log it to a file, or a database, or a cloud service of some kind.  In call these cases the data leaves the process that created it and MUST BE SERIALIZED.    As anyone who has dealt with serialization before knows, serialization is a 'hard' problem because frankly not all object can be 'copied' which is what you are trying to do when you serialize something.   Thus serialization schemes very quickly get complex and subtle, which are not good things in general, and especially in something like EventSource that is supposed to be used by 'everything' to do logging.

Thus there have to be rules that keep the data serializable.    The 'sweet spot' that EventSource picked can be summed up as 'Typed JSON'.   JSON can be thought of roughly as a the type closer of strings, structures, and arrays nested in a arbitrary way.    EventSource rich data does the same, but keeps the strong typing.  Thus you can have arrays and structures as well as primitive types, nested in arbitrary way.   Any type that implements IEnumerable<T> can be used as a value for an array, but for structures not just any type can be used.   It must be either

  1. A type marked with the [EventData] attribute.   This makes it clear that this type was intended to be serializable by EventSource.   The rule is that EventSource will serialize EVERY public PROPERTY (it does not do fields, only properties), and the types of those properties much follow the serializable rules.
  2. You can also use anonymous types (e.g  new { X = 3, y = "Hello"} to specify structure values. 

For example it is legal to have a declaration like this

  • void LogComplexValue(string name, object complexValue) { WriteEvent(3, name, complexValue); }

And a call site of

  •  myEventSource.LogComplexValue("hello", new { field1="hi", location = new { x = 3.4, y = 5.0 } }); 

 Which passes an object with a structure as 'complexValue' which has two fields. The first field is named  'field1' of type string and the second is named 'location' which is a structure with an 'x' and 'y' field of type double.  See the EventSoruce Rich Data Payloads spec for more details. 

Receiving Complex Values in EventListeners

Once you have logged a complex value with an EventSource, it is natural to ask exactly how you receive in an EventListener.    An important point is that EventListeners preserve the idea that the data is a COPY OF THE DATA.   Thus you do not get the object itself but a COPY OF THE DATA in your EventListener.    Thus you should not expect object identity, or event the same type.   In fact the rules are

  1. If the data item is an array, all you will know in the Listener is that it implemented IEnumerable<T> for some T
  2. If the data item is a structure, the object passed back in the listener implements IDictionary<string, T> for some T, where the keys are the field names, and the values are the field values.
  3. If the data item is a primitive type or string, a copy is passed through.    

Notice that in the case of a structure, an important transformation has happened, you passed in a object representing a T (often this type is anonymous) but what you get out is a IDictionary<string, T>, which is certainly not a T, however it is MORE CONVINIENT, since you don't need to use reflection to fetch the field values (which is what you would have to do otherwise in the common case that the value was an anonymous type).  See the EventSoruce Rich Data Payloads spec for more details. 

Rich Data Only Supported in Self-Describing ETW

If you are receiving data via EventListeners, you can skip this section as it only pertains to the case when EventSource data flows through the windows ETW system.   Before windows 10, ETW data needed to be declared using a 'manifest' and this manifest had to describe every possible event.   In Windows 10 a new 'self-describing' ETW format was introduced that does need the manifest.   This mechanism was also back-ported into WIndows 8 and 7 (although on those OSes you have to have a recent-enough servicing update).  

The key point, however is that rich data does NOT work on Manifest-based ETW, only on the newer 'self-describing' ETW format.   What his means to you is that if you are using rich data formats AND ETW you need to

  • Indicate to EventSource to use the newer format.   You do that by using the EventSource constructor that takes a EventSourceSettings argument and pass the EvetnSourceSettings.EtwSelfDescrigingEventFormat value.   It would look the line in blue below. 

    class MyEventSource : EventSource
    {
        private MyEventSource() : base(EventSourceSettings.EtwSelfDescribingEventFormat) { }

        public static MyEventSource Logger = new MyEventSource();

        // Definitions of events as normal...
    }

  •  If you use the EventSource(string) overload to create the EventSource (which is designed for use with the Write<T> API) it uses the Self-describing format by default so you don't need to do anything special
  • You need to be on an OS which supports the self-describing format (either Windows 10 or a late update to Windows 8 or 7).

Guidance

It is pretty important to realize that Rich data type ARE TRICKIER, then just using primitives.   They are also SIGNIFNCATNLY MORE EXPENSIVE.    Exactly how much more depends on what you are doing but a good rule of thumb is that if you are generating more than 100 events /second you should be concerned.  If you are over 10 events/sec you should be measuring and seeing just where you stand with respect to performance. 

Also keep in mind that there are other ways of dumping data into a payload.   In particular you could always serialize the data you want to send yourself as JSON and then just send that string as a field in EventSouce payload.   This makes ALOT of sense if you ALREADY had to generate the JSON payload anyway, because you can pass it through easily.  

I compare the Rich datatype support in EventSource much like reflection in the .NET Runtime.  It is a powerful feature, and when you REALLY need it is INDISPENSIBLE.   However like reflection it is expensive, and should be used with some care, with an understanding of its performance penalty.    If you are using it everywhere, and you log events frequently you are probably using it poorly. 

Summary

EventSource has a new ability to pass rich JSON-like payloads from EventSources to EventListeners (and ETW, on appropriate OSes).   It is available on V4.6 runtimes as well as the EventSource Nuget Package.    It is a powerful feature (like reflection), but also has a non-trivial cost (like reflection), so should be used with some care (like reflection), and performance measurements should be done if it is used on hot paths.   For more information see the EventSoruce Rich Data Payloads spec attached to this blog entry.

EventSourceRichPayloads.docx

Comments

  • Anonymous
    September 24, 2015
    Is the Self-Describing ETW format able to describe the names and values of enum constants, like valueMap elements do in a Windows Event Log instrumentation manifest?

  • Anonymous
    September 24, 2015
    This is a good question.  The answer currently is 'no' the self-describing format does not include information for decoding enumerations and bitsets (like manifest-based ETW does).   This is something that could be added, but there is no support for it at the present time.

  • Anonymous
    September 24, 2015
    As far as the core TraceLogging protocol goes -- I would like to add that feature, but it would be rather expensive in terms of event size. In addition, it would be very hard to make this work anywhere except .NET. For example, C++ does not have any way to reflect over the list of enumeration values. Specific implementations of TraceLogging (e.g. EventSource) are free to do whatever they like as far as translating the implementation-specific data into a TraceLogging event. It might be feasible for EventSource to turn each enum value into two fields -- one with the integer value of the enum, and one with the string value of the enum.

  • Anonymous
    September 24, 2015
    I was thinking the event source would describe the enum type just once as a separate event and assign an integer ID to the enum type, then refer to that ID in subsequent events. Plus have a way for consumers to request listing all the types again. It would be even better if the event source could add more names and values to the enum type at run time, e.g. based on a configuration file. So if the configuration lists a set of objects that the event source manipulates, then it could assign an ID to each object, treat that set as an enum, keep the event payloads small by emitting those IDs instead of name strings, and still have the names appear in the event subscriber UI.

  • Anonymous
    September 25, 2015
    So you could have an empty or almost empty enum type, like [EventData] public enum CipherSuite { None = 0 } then register more values at run time myEventSource.RegisterEnumValue((CipherSuite)1, "DH-RSA-AES128-GCM-SHA256"); myEventSource.RegisterEnumValue((CipherSuite)2, "SRP-DSS-AES-256-CBC-SHA"); and write those out as properties of EventSource-serializable structures. The ID scheme that I suggested in my previous comment would deviate a bit from the "each TraceLogging event includes its own decoding information" principle, but the payload format could be defined such that an event decoder can always locate the name-value pairs and decode the enum-typed values as integers, even if it missed the events that carried the enum type definitions.

  • Anonymous
    September 30, 2015
    With a server recently updated to .NET 4.6 (along with other September patches), instances of TraceEvent FormattedMessage now show portions such as "%t" where they formerly showed " " or "%%" where formerly it was just "%". Is this another, expected change in behavior of 4.6 EventSource?

  • Anonymous
    October 01, 2015
    I don't recognize the issue you are describing as something that is known/expected.   To my knowledge we have not fiddle with formatted strings in EventSource in V4.6.   We have however fiddled with formatted strings in TraceEvent, but even there I would not expect the behavior you describe.   There have been bug fixes in formatted strings predating V4.6, which may be in play here.   Please describe exactly what you did and what shows up.    If you can publish an ETL file that would be very helpful.

  • Anonymous
    October 01, 2015
    I have the following details of a test I ran: Regarding two custom EventSource methods with the following EventAttribute Messages containing a tab "t":  "Service Starting:{1}tThread:{0}";  "Service heartbeattThread:{0}"; I executed the following test:

  • Restored a Windows 8 snapshot from July 30, 2015, where framework 4.5.1 is installed

  • Built my application to target framework 4.5.1

  • Installed SemanticLogging-svc.2.0.1406.1

  • Started a SemanticLogging RollingFlatFileSink to capture my event source

  • Started my application to raise the events described above, captured in the file as the   following, where a tab "t" is in FormattedMessage as a space " ":    +=======================================+    EventId : 2100, Level : Informational, Message : Service Starting:NotificationService Thread:1, ...*    +=======================================+    EventId : 2103, Level : Informational, Message : Service heartbeat Thread:5, ... Then I performed the following:

  • Updated the running snapshot to framework 4.6

  • Rebooted, as instructed by the 4.6 Web Installer. This was just "Reboot" not "Update   and Reboot"; but the event log shows the system installing some updates anyway around   this time

  • Re-built my application to target framework 4.5.1

  • Re-started the SemanticLogging-svc.2.0.1406.1 RollingFlatFileSink

  • Re-started my application to raise some events, captured in the file as the following,   where a tab "t" is now in FormattedMessage as two characters "%t":    +=======================================+    EventId : 2100, Level : Informational, Message : Service Starting:NotificationService%tThread:1, ...    +=======================================+    EventId : 2103, Level : Informational, Message : Service heartbeat%tThread:5, ... Then I tried the following:

  • Uninstall .NET frameworks

  • Install the 4.5.1 DevPack (NDP451-KB2861696-x86-x64-DevPack) which is what had been   installed for that snapshot (installer instructed to reboot and restart it)

  • Rebooted after installing (though not prompted)

  • Re-built my application to target framework 4.5.1

  • Re-started a SemanticLogging-svc.2.0.1406.1 RollingFlatFileSink

  • Re-started my application to raise some events, captured in the file as the following,   where a tab "t" continues to be in FormattedMessage as two characters "%t":    +=======================================+    EventId : 2100, Level : Informational, Message : Service Starting:NotificationService%tThread:1, ...    +=======================================+    EventId : 2103, Level : Informational, Message : Service heartbeat%tThread:5, ... Having reverted to 4.5.1, I wonder now whether a Windows update is responsible for the different behavior. Thank you for any advice you can give. (I did not include an example with an EventAttribute Message containing a "%", but those are now "%%" in FormattedMessage on updated workstations and servers). *shortened for msdn.com limits

  • Anonymous
    October 12, 2015
    Hello again. Please see github.com/.../event_formatted_message. I have captured ETLs as you asked and included the source code for a Event that demonstrates the new 4.6.0 behavior for tabs and % characters. Thank you.

  • Anonymous
    October 14, 2015
    The comment has been removed

  • Anonymous
    October 14, 2015
    The Demo code was wrong.   I have uploaded a fixed document.   It was using Write() instead of the WriteEvent() method here is the fixed code        public void LogSimpleData(string message, SimpleData data) { WriteEvent(1, message, data); }        public void LogArray(string message, IEnumerable<int> data) { WriteEvent(2, message, data); }        public void LogNode(string message, NodeData data) { WriteEvent(3, message, data); }        public void LogDictionary(string message, Dictionary<string, int> keyValues)            { WriteEvent(4, message, keyValues); } It is also possible to fix this to use Write() for example     [NonEvent]     public void LogSimpleData(string message, SimpleData data) {           Write("LogSimpleData", new {message =  message, data = data}); } However generally we don't recommend using dynamically defined events when statically define events (WriteEvent) will work. Sorry about the incorrect demo, and thanks for the bug report.    Let me know if this does not fix the problem.

  • Anonymous
    October 21, 2015
    Regarding Self-Describing ETW and "This mechanism was also back-ported into Windows 8 and 7 (although on those OSes you have to have a recent-enough servicing update).".... can you comment regarding the requirements for Win 7?   We have older (unpatched) systems deployed in disconnected scenarios in the field and we are about to deploy an app using ETW (self described).  Can you tell me any more about what we will have to insure is installed on the Win 7 system for our code to work?  Thanks.

  • Anonymous
    November 20, 2015
    Hello Vance, We are in the midst of creating EventSources in C++ CLI, and are running across a compiler warning I'm wondering if you've dealt with. warning C4538: 'cli::array<Type,dimension> ^' : const/volatile qualifiers on this type are not supported 1>          with 1>          [ 1>              Type=System::Diagnostics::Tracing::EventSource::EventMetadata, 1>              dimension=1 1>          ] 1>          This diagnostic occurred while importing type 'System::Diagnostics::Tracing::EventSource ' from assembly 'mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089'. There is one post no StackOverflow about this (stackoverflow.com/.../warning-c4538-when-using-systemdiagnosticstracingeventsource-on-c) but no real explanation.  The only solution is to just disable the warning with #pragma warning (disable: 4538) If this is a 'compiler bug' as some are saying, would you by chance have any documentation on it?

  • Anonymous
    November 20, 2015
    The compiler is complaining because inside the implementation of EventSource there is an internal field of type EventMetaData that is volatile.     This is a bug in the C++ compiler because although C++ may not support volatile, it should not complain about code generated by others unless it actually causes a problem with the code C++ is generating.     Disabling the warning with a #pragma seems like a reasonable work-around.   Feel free to log the bug on the connect site.  

  • Anonymous
    December 30, 2015
    download file seems to be corrupted...

  • Anonymous
    December 30, 2015
    download file seems to be corrupted

  • Anonymous
    January 04, 2016
    @Joe Healy:  I am not sure what download file you are referring to.  In this blog there is only only a attached word document (EventSourceRichPayloads.docx) which opens fine for me.

  • Anonymous
    July 17, 2016
    Hi, I got Event Source from NuGet, version 1.1.28 and wrote a simple test, I believe from the doc.using Microsoft.Diagnostics.Tracing;namespace ConsoleApplication3{ [EventData] public class SimpleData { public string Name { get; set; } public int Address { get; set; } } [EventSource(Name = "Samples-EventSourceDemos-RuntimeDemo")] public sealed class RuntimeDemoEventSource : EventSource { // define the singleton instance of the event source public static RuntimeDemoEventSource Log = new RuntimeDemoEventSource(); // define a new event. public void LogSimpleData(string message, SimpleData data) { WriteEvent(1, message, data); } }}However, it fails when rebuilding:1>EXEC : error : ConsoleApplication3.RuntimeDemoEventSource: Unsupported type SimpleData in event source.1>EXEC : error : ConsoleApplication3.RuntimeDemoEventSource: Generation of ETW manifest failed1>EXEC : error : Failures encountered creating registration DLLs for EventSources in c:\users\il\documents\visual studio 2015\Projects\ConsoleApplication3\ConsoleApplication3\bin\x64\Debug\ConsoleApplication3.exe1>c:\users\il\documents\visual studio 2015\Projects\ConsoleApplication3\packages\Microsoft.Diagnostics.Tracing.EventRegister.1.1.28\build\Microsoft.Diagnostics.Tracing.EventRegister.targets(132,5): error MSB3073: The command ""c:\users\il\documents\visual studio 2015\Projects\ConsoleApplication3\packages\Microsoft.Diagnostics.Tracing.EventRegister.1.1.28\build\eventRegister.exe" -DumpRegDlls @"c:\users\il\documents\visual studio 2015\Projects\ConsoleApplication3\ConsoleApplication3\bin\x64\Debug\ConsoleApplication3.eventRegister.rsp" "c:\users\il\documents\visual studio 2015\Projects\ConsoleApplication3\ConsoleApplication3\bin\x64\Debug\ConsoleApplication3.exe" " exited with code 1.Am I missing something obvious?Thank you for you timeIL

  • Anonymous
    September 01, 2016
    @Vance very nice blog! I'm working on building a logging library for our system and planning to use ETW logging. Support for complex types is a nice addition to EventSource. Our system is expected to emit more that 100 events/sec, so performance is definitely going to be an issue like you mentioned. If I serialize the JSON before-hand and pass it as a string, the existing trace listeners we have is going to consider it as a single field, but we want each key-value in the JSON to be considered as a separate field, like when we pass in the complex object with EventData attribute. Is there another way to optimize it ?