{"id":5698,"date":"2020-01-06T15:00:15","date_gmt":"2020-01-06T15:00:15","guid":{"rendered":"http:\/\/writeasync.net\/?p=5698"},"modified":"2020-01-04T18:10:30","modified_gmt":"2020-01-04T18:10:30","slug":"eventsource-and-span-take-1","status":"publish","type":"post","link":"https:\/\/writeasync.net\/?p=5698","title":{"rendered":"EventSource and Span: take 1"},"content":{"rendered":"

Let’s say you’re living the zero-allocation, universal memory<\/a> .NET life, and you need to trace some char<\/code> data. The only problem is that you have a Span<char><\/a> and EventSource only supports string<\/a>. What to do?<\/p>\n

We’ll start with a typical EventSource implementation using string<\/code>:<\/p>\n

\r\n    [EventSource(Guid = "c451aca3-50ae-4955-9723-38b9ae7d98c0")]\r\n    public sealed class MyEventSource : EventSource\r\n    {\r\n        public static readonly MyEventSource Instance = new MyEventSource();\r\n\r\n        private MyEventSource()\r\n        {\r\n        }\r\n\r\n        [Event(1, Message = "Hello {0} {1} {2}")]\r\n        public void Hello(int n1, int n2, string s1)\r\n        {\r\n            this.WriteEvent(1, n1, n2, s1);\r\n        }\r\n    }\r\n<\/pre>\n
This generates a manifest like the following:<\/p>\n
\r\n<instrumentationManifest xmlns="http:\/\/schemas.microsoft.com\/win\/2004\/08\/events">\r\n <instrumentation xmlns:xs="http:\/\/www.w3.org\/2001\/XMLSchema" xmlns:xsi="http:\/\/www.w3.org\/2001\/XMLSchema-instance" xmlns:win="http:\/\/manifests.microsoft.com\/win\/2004\/08\/windows\/events">\r\n  <events xmlns="http:\/\/schemas.microsoft.com\/win\/2004\/08\/events">\r\n<provider name="MyEventSource" guid="{c451aca3-50ae-4955-9723-38b9ae7d98c0}" resourceFileName="x.dll" messageFileName="x.dll" symbol="MyEventSource">\r\n <tasks>\r\n  <task name="Hello" message="$(string.task_Hello)" value="65533"\/>\r\n  <task name="EventSourceMessage" message="$(string.task_EventSourceMessage)" value="65534"\/>\r\n <\/tasks>\r\n <opcodes>\r\n <\/opcodes>\r\n <keywords>\r\n  <keyword name="Session3" message="$(string.keyword_Session3)" mask="0x100000000000"\/>\r\n  <keyword name="Session2" message="$(string.keyword_Session2)" mask="0x200000000000"\/>\r\n  <keyword name="Session1" message="$(string.keyword_Session1)" mask="0x400000000000"\/>\r\n  <keyword name="Session0" message="$(string.keyword_Session0)" mask="0x800000000000"\/>\r\n <\/keywords>\r\n <events>\r\n  <event value="0" version="0" level="win:LogAlways" symbol="EventSourceMessage" task="EventSourceMessage" template="EventSourceMessageArgs"\/>\r\n  <event value="1" version="0" level="win:Informational" symbol="Hello" message="$(string.event_Hello)" task="Hello" template="HelloArgs"\/>\r\n <\/events>\r\n <templates>\r\n  <template tid="EventSourceMessageArgs">\r\n   <data name="message" inType="win:UnicodeString"\/>\r\n  <\/template>\r\n  <template tid="HelloArgs">\r\n   <data name="n1" inType="win:Int32"\/>\r\n   <data name="n2" inType="win:Int32"\/>\r\n   <data name="s1" inType="win:UnicodeString"\/>\r\n  <\/template>\r\n <\/templates>\r\n<\/provider>\r\n<\/events>\r\n<\/instrumentation>\r\n<localization>\r\n <resources culture="en-US">\r\n  <stringTable>\r\n   <string id="event_Hello" value="Hello %1 %2 %3"\/>\r\n   <string id="keyword_Session0" value="Session0"\/>\r\n   <string id="keyword_Session1" value="Session1"\/>\r\n   <string id="keyword_Session2" value="Session2"\/>\r\n   <string id="keyword_Session3" value="Session3"\/>\r\n   <string id="task_EventSourceMessage" value="EventSourceMessage"\/>\r\n   <string id="task_Hello" value="Hello"\/>\r\n  <\/stringTable>\r\n <\/resources>\r\n<\/localization>\r\n<\/instrumentationManifest>\r\n<\/pre>\n
Finally, a complete self-contained sample to trace and collect the EventSource data:<\/p>\n
\r\n    internal sealed class Program\r\n    {\r\n        private static void Main()\r\n        {\r\n            const string TraceName = "SampleTrace";\r\n            const string TracePath = "SampleTrace.etl";\r\n            const string ManifestPath = "SampleTrace.man";\r\n            string providerId = EventSource.GetGuid(typeof(MyEventSource)).ToString("b");\r\n            File.WriteAllText(ManifestPath, EventSource.GenerateManifest(typeof(MyEventSource), "x.dll"));\r\n            Logman("create trace", TraceName, "-ow -o", TracePath, "-p", providerId, "0xFFFFFFFFFFFFFFFF 5");\r\n            Logman("start", TraceName);\r\n            \r\n            MyEventSource.Instance.Hello(1, 2, "three");\r\n            \r\n            Logman("stop", TraceName);\r\n            Logman("delete", TraceName);\r\n            FileInfo traceFile = new DirectoryInfo(".").EnumerateFiles("SampleTrace*.etl").Last();\r\n            Exec("tracerpt.exe", "-y -l", traceFile.FullName, "-import", ManifestPath);\r\n        }\r\n\r\n        private static void Logman(params string[] args) => Exec("logman.exe", args);\r\n\r\n        private static void Exec(string fileName, params string[] args)\r\n        {\r\n            using Process process = Process.Start(fileName, string.Join(' ', args));\r\n            process.WaitForExit();\r\n            if (process.ExitCode != 0)\r\n            {\r\n                throw new InvalidOperationException($"{fileName} failed with code {process.ExitCode}.");\r\n            }\r\n        }\r\n    }\r\n<\/pre>\n
We’re using logman.exe to create the trace collector and tracerpt.exe to decode the ETL data<\/a>. The resulting dumpfile.xml shows the expected event data:<\/p>\n
\r\n\t<EventData>\r\n\t\t<Data Name="n1">1<\/Data>\r\n\t\t<Data Name="n2">2<\/Data>\r\n\t\t<Data Name="s1">three<\/Data>\r\n\t<\/EventData>\r\n<\/pre>\n
Obviously, this EventSource does not meet our requirements. It uses a string and also the slow WriteEvent overload<\/a>. Let’s fix the latter problem:<\/p>\n
\r\n    [EventSource(Guid = "c451aca3-50ae-4955-9723-38b9ae7d98c0")]\r\n    public sealed class MyEventSource : EventSource\r\n    {\r\n        public static readonly MyEventSource Instance = new MyEventSource();\r\n\r\n        private MyEventSource()\r\n        {\r\n        }\r\n\r\n        [Event(1, Message = "Hello {0} {1} {2}")]\r\n        public unsafe void Hello(int n1, int n2, string s1)\r\n        {\r\n            if (this.IsEnabled())\r\n            {\r\n                s1 ??= string.Empty;\r\n                fixed (char* _s1 = s1)\r\n                {\r\n                    EventData* descrs = stackalloc EventData[3];\r\n                    descrs[0].DataPointer = (IntPtr)(&n1);\r\n                    descrs[0].Size = sizeof(int);\r\n                    descrs[1].DataPointer = (IntPtr)(&n2);\r\n                    descrs[1].Size = sizeof(int);\r\n                    descrs[2].DataPointer = (IntPtr)_s1;\r\n                    descrs[2].Size = (s1.Length + 1) * 2;\r\n                    this.WriteEventWithRelatedActivityIdCore(1, null, 3, descrs);\r\n                }\r\n            }\r\n        }\r\n    }\r\n<\/pre>\n
It’s not pretty to look at but it has the same outcome as the simple version without the overhead. Still, we haven’t solved the Span problem. How can we get EventSource to accept a nonstandard event signature while still generating a proper manifest?<\/p>\n
It turns out that event methods do not have to be public, so we can write the undesirable string version as a private method. Then we can use [NonEvent]<\/a> methods to implement the Span logic that we need:<\/p>\n
\r\n    [EventSource(Guid = "c451aca3-50ae-4955-9723-38b9ae7d98c0")]\r\n    public sealed class MyEventSource3 : EventSource\r\n    {\r\n        public static readonly MyEventSource3 Instance = new MyEventSource3();\r\n\r\n        private MyEventSource3()\r\n        {\r\n        }\r\n\r\n        [NonEvent]\r\n        public void Hello(int n1, int n2, ReadOnlySpan<char> s1)\r\n        {\r\n            this.HelloCore(n1, n2, s1);\r\n        }\r\n\r\n        [Event(1, Message = "Hello {0} {1} {2}")]\r\n        private void Hello(int n1, int n2, string s1)\r\n        {\r\n            this.HelloCore(n1, n2, s1);\r\n        }\r\n\r\n        [NonEvent]\r\n        private unsafe void HelloCore(int n1, int n2, ReadOnlySpan<char> s1)\r\n        {\r\n            if (this.IsEnabled())\r\n            {\r\n                fixed (char* _s1 = s1)\r\n                {\r\n                    EventData* descrs = stackalloc EventData[3];\r\n                    descrs[0].DataPointer = (IntPtr)(&n1);\r\n                    descrs[0].Size = sizeof(int);\r\n                    descrs[1].DataPointer = (IntPtr)(&n2);\r\n                    descrs[1].Size = sizeof(int);\r\n                    descrs[2].DataPointer = (IntPtr)_s1;\r\n                    descrs[2].Size = (s1.Length + 1) * 2;\r\n                    this.WriteEventWithRelatedActivityIdCore(1, null, 3, descrs);\r\n                }\r\n            }\r\n        }\r\n    }\r\n<\/pre>\n
(Note that since string is implicitly convertible to Span<char>, we can call the “core” method in both situations.)<\/p>\n
We need one modification of the main program to demonstrate the Span case:<\/p>\n
\r\n            const string Str = "threeeeeeeeeeee";\r\n            ReadOnlySpan<char> s = Str.AsSpan(0, 5);\r\n            MyEventSource.Instance.Hello(1, 2, s);\r\n<\/pre>\n
The generated manifest is identical, so that’s a win. Unfortunately, the data is not what we expected<\/strong>:<\/p>\n
\r\n\t<EventData>\r\n\t\t<Data Name="n1">1<\/Data>\r\n\t\t<Data Name="n2">2<\/Data>\r\n\t\t<Data Name="s1">threee<\/Data>\r\n\t<\/EventData>\r\n<\/pre>\n
We expected “three” but got “threee”. The problem is here:<\/p>\n
\r\n                    descrs[2].Size = (s1.Length + 1) * 2;\r\n<\/pre>\n
ETW expects all strings to be null-terminated, but we are using a span which is a five character prefix from a larger string, no more and no less. What we have here is an out of bounds error<\/a> that is not reported by the runtime. When we said unsafe<\/code><\/a> we meant it!<\/p>\n
All we wanted was allocation-free string data tracing, but it would seem that we’re out of luck here with Span. Is there any way around this limitation? We’ll find out, when we pick up this investigation later…<\/p>\n","protected":false},"excerpt":{"rendered":"
Let’s say you’re living the zero-allocation, universal memory .NET life, and you need to trace some char data. The only problem is that you have a Span<char> and EventSource only supports string. What to do? We’ll start with a typical… <\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[71,104],"tags":[],"class_list":["post-5698","post","type-post","status-publish","format-standard","hentry","category-diagnostics","category-performance"],"_links":{"self":[{"href":"https:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/posts\/5698","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/writeasync.net\/index.php?rest_route=%2Fwp%2Fv2%2Fcomments&post=5698"}],"version-history":[{"count":1,"href":"https:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/posts\/5698\/revisions"}],"predecessor-version":[{"id":5699,"href":"https:\/\/writeasync.net\/index.php?rest_route=\/wp\/v2\/posts\/5698\/revisions\/5699"}],"wp:attachment":[{"href":"https:\/\/writeasync.net\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=5698"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/writeasync.net\/index.php?rest_route=%2Fwp%2Fv2%2Fcategories&post=5698"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/writeasync.net\/index.php?rest_route=%2Fwp%2Fv2%2Ftags&post=5698"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}