microsoft / perfview

PerfView is a CPU and memory performance-analysis tool
http://channel9.msdn.com/Series/PerfView-Tutorial
MIT License
4.05k stars 695 forks source link

Missing TraceEventParser for EventSource "Microsoft-Diagnostics-DiagnosticSource" #2010

Closed ps-weber closed 3 months ago

ps-weber commented 3 months ago

I want to parse events emitted by the ActivitySource class from the Nuget package System.Diagnostics.DiagnosticSource as described here. Recording the events via TraceEvent/PerfView works and I can see all the data in PerfView.

However, I can not read all fields via TraceEvent. The default DynamicTraceEventParser can not parse nested collections (These are created using *Enumerate). I tried generating a TraceEventParser according to the tutorial, but do not get a manifest for Microsoft-Diagnostics-DiagnosticSource. I can only find the manifest for "System.Diagnostics.Metrics" which I also use.

Also I think there is a small mistake in the tutorial, when i try the command PerfView /onlyProviders=*Microsoft-Diagnostics-DiagnosticSource EventSource collect I get an error "Error EventSource not a perfView command"

ps-weber commented 3 months ago

I gave it a try and this is what I was able to come up with:

using System;
using System.Collections.Generic;
using System.Text;
using System.Diagnostics;
using Microsoft.Diagnostics.Tracing;

internal class MicrosoftDiagnosticSourceEventParser : TraceEventParser
{
    public static readonly string ProviderName = "Microsoft-Diagnostics-DiagnosticSource";
    // {adb401e1-5296-51f8-c125-5fda75826144}
    public static readonly Guid ProviderGuid = new Guid(unchecked((int)0xadb401e1), unchecked((short)0x5296), unchecked((short)0x51f8), 0xc1, 0x25, 0x5f, 0xda, 0x75, 0x82, 0x61, 0x44);

    public MicrosoftDiagnosticSourceEventParser(TraceEventSource source) : base(source) { }

    public event Action<CoreActivityTraceData> CoreActivityStop
    {
        add
        {
            RegisterTemplate(new CoreActivityTraceData(value, eventID: 65277, task: default, taskName: "CoreActivity", taskGuid: default, opcode: 2, "Stop", ProviderGuid, ProviderName));
        }
        remove
        {
            source.UnregisterEventTemplate(value, 1, ProviderGuid);
        }
    }

    public event Action<FrameworkActivityTraceData> FrameworkActivityStop
    {
        add
        {
            RegisterTemplate(new FrameworkActivityTraceData(value, eventID: 65276, task: default, taskName: "FrameworkActivity", taskGuid: default, opcode: 2, "Stop", ProviderGuid, ProviderName));
        }
        remove
        {
            source.UnregisterEventTemplate(value, 1, ProviderGuid);
        }
    }

    protected override string GetProviderName() => ProviderName;

    private static volatile TraceEvent[]? s_templates;

    protected override void EnumerateTemplates(Func<string, string, EventFilterResponse> eventsToObserve, Action<TraceEvent> callback)
    {
        if (s_templates == null)
        {
            // TODO ActivityStart should be pretty easy to do
            var templates = new TraceEvent[2];
            templates[0] = new CoreActivityTraceData(null!, eventID: 65277, task: default, taskName: "CoreActivity", taskGuid: default, opcode: 2, "Stop", ProviderGuid, ProviderName);
            templates[1] = new FrameworkActivityTraceData(null!, eventID: 65276, task: default, taskName: "FrameworkActivity", taskGuid: default, opcode: 2, "Stop", ProviderGuid, ProviderName);

            s_templates = templates;
        }

        foreach (var template in s_templates)
        {
            if (eventsToObserve == null || eventsToObserve(template.ProviderName, template.EventName) == EventFilterResponse.AcceptEvent)
            {
                callback(template);
            }
        }
    }

    private void RegisterTemplate(TraceEvent template)
    {
        Debug.Assert(template.ProviderGuid == MicrosoftDiagnosticSourceEventParser.ProviderGuid);
        source.RegisterEventTemplate(template);
    }
}

public sealed class CoreActivityTraceData : ActivityTraceData
{
    public override string SourceName => GetUnicodeStringAt(0);

    public override string ActivityName => GetUnicodeStringAt(SkipUnicodeString(0));

    public override KeyValuePair<string, string>[] Arguments
    {
        get
        {
            int offset = SkipUnicodeString(0, 2);
            int count = GetInt16At(offset);
            offset += 2;
            var arr = new KeyValuePair<string, string>[count];
            for (int i = 0; i < count; i++)
            {
                var key = GetUnicodeStringAt(offset);
                offset = SkipUnicodeString(offset);

                var value  = GetUnicodeStringAt(offset);
                offset = SkipUnicodeString(offset);

                arr[i] = new KeyValuePair<string, string>(key, value);
            }

            return arr;
        }
    }

    internal string GetFixedUnicodeStringAt(int charCount, int offset)
    {
        // You could do fancy unsafe stuff here, but im ok with the StringBuilder for now
        StringBuilder sb = new StringBuilder(charCount);
        for (int i = 0; i < charCount; i++)
        {
            char c = (char)GetInt16At(offset + i * 2);
            if (c == 0)
            {
                break;
            }

            sb.Append(c);
        }
        return sb.ToString();
    }

    internal CoreActivityTraceData(Action<CoreActivityTraceData> action, int eventID, int task, string taskName, Guid taskGuid, int opcode, string opcodeName, Guid providerGuid, string providerName)
        : base(eventID, task, taskName, taskGuid, opcode, opcodeName, providerGuid, providerName)
    {
        Action = action;
    }

    protected override void Dispatch()
    {
        Action(this);
    }

    protected override Delegate Target
    {
        get { return Action; }
        set { Action = (Action<CoreActivityTraceData>)value; }
    }

    private event Action<CoreActivityTraceData> Action;
}

public abstract class ActivityTraceData : TraceEvent
{
    protected ActivityTraceData(int eventID, int task, string taskName, Guid taskGuid, int opcode, string opcodeName, Guid providerGuid, string providerName)
        : base(eventID, task, taskName, taskGuid, opcode, opcodeName, providerGuid, providerName)
    {
    }

    public abstract string SourceName { get; }

    public abstract string ActivityName { get; }

    public abstract KeyValuePair<string, string>[] Arguments { get; }

    public override StringBuilder ToXml(StringBuilder sb)
    {
        Prefix(sb);
        XmlAttrib(sb, "SourceName", SourceName);
        XmlAttrib(sb, "ActivityName", ActivityName);
        sb.AppendLine(">");
        foreach (var kv in Arguments)
        {
            sb.Append("<Argument");
            XmlAttrib(sb, "Name", kv.Key);
            XmlAttrib(sb, "Value", kv.Value);
            sb.Append("/>");
            sb.AppendLine();
        }
        sb.Append("</Event>");
        return sb;
    }

    public override string[] PayloadNames
    {
        get
        {
            if (payloadNames == null)
            {
                payloadNames = new string[] { "SourceName", "ActivityName", "Arguments" };
            }

            return payloadNames;
        }
    }

    public override object PayloadValue(int index)
    {
        switch (index)
        {
            case 0:
                return SourceName;
            case 1:
                return ActivityName;
            case 2:
                return Arguments;
            default:
                Debug.Assert(false, "Bad field index");
                return null;
        }
    }
}

public sealed class FrameworkActivityTraceData : ActivityTraceData
{
    public override string SourceName => GetFixedUnicodeStringAt(GetInt16At(0) / 2, 2);

    public override string ActivityName 
    {
        get
        {
            int offset = 2 + GetInt16At(0); // length + string
            var length = GetInt16At(offset) / 2;
            return GetFixedUnicodeStringAt(length, offset + 2);
        }
    }

    public override KeyValuePair<string, string>[] Arguments
    {
        get
        {
            int offset = 2 + GetInt16At(0); // Skip first string
            offset += 2 + GetInt16At(offset); // Skip second string

            int count = GetInt16At(offset);
            offset += 2;
            var arr = new KeyValuePair<string, string>[count];
            for (int i = 0; i < count; i++)
            {
                int length = GetInt16At(offset);
                offset += 2;
                var key = GetFixedUnicodeStringAt(length / 2, offset);
                offset += length;

                length = GetInt16At(offset);
                offset += 2;
                var value = GetFixedUnicodeStringAt(length / 2, offset);
                offset += length;

                arr[i] = new KeyValuePair<string, string>(key, value);
            }

            return arr;
        }
    }

    internal string GetFixedUnicodeStringAt(int charCount, int offset)
    {
        // You could do fancy unsafe stuff here, but im ok with the StringBuilder for now
        StringBuilder sb = new StringBuilder(charCount);
        for (int i = 0; i < charCount; i++)
        {
            char c = (char)GetInt16At(offset + i * 2);
            if (c == 0)
            {
                break;
            }

            sb.Append(c);
        }
        return sb.ToString();
    }

    internal FrameworkActivityTraceData(Action<FrameworkActivityTraceData> action, int eventID, int task, string taskName, Guid taskGuid, int opcode, string opcodeName, Guid providerGuid, string providerName)
        : base(eventID, task, taskName, taskGuid, opcode, opcodeName, providerGuid, providerName)
    {
        Action = action;
    }

    protected override void Dispatch()
    {
        Action(this);
    }

    protected override Delegate Target
    {
        get { return Action; }
        set { Action = (Action<FrameworkActivityTraceData>)value; }
    }

    private event Action<FrameworkActivityTraceData> Action;
}
brianrob commented 3 months ago

@ps-weber, you're right that there isn't a manifest for DiagnosticSource. This is because it uses the ETW self-describing format, which means that the metadata is stored with the event itself.

DynamicTraceEventParser is capable of parsing nested structs. Here's an example that I just ran:

using EventSource source = new EventSource("SelfDescribing-Test", EventSourceSettings.EtwSelfDescribingEventFormat);
source.Write("Nested", new { A = "A", B = "B", C = new { D = "D", E = "E"}, F= "F" });
Event Name                  Time MSec   Process Name    Rest  
SelfDescribing-Test/Nested  5,407.933   app (10336)     ThreadID="16,972" ProcessorNumber="2" A="A" B="B" C="{ "D":"D", "E":"E" }" F="F" 

It is certainly reasonable to write code like what you've written above to parse these events instead of using DynamicTraceEventParser, but you should be able to get this data out using DynamicTraceEventParser should you want to.

You are right on the documentation bug - thanks for reporting this. I have posted https://github.com/microsoft/perfview/pull/2014.

ps-weber commented 3 months ago

Ok, this resolve it for me.

What I meant by "nested collection" is that I wanted to recover the elements of the collection I collected via *Enumerate. However, these get string-joined in the DiagnosticSourceEventSource, and since the contents of the IEnumerable may contain a comma, they can not be recovered reliably. A fix for this would need to be implemented on the collection side an not in PerfView.

brianrob commented 3 months ago

Ok, this resolve it for me.

What I meant by "nested collection" is that I wanted to recover the elements of the collection I collected via *Enumerate. However, these get string-joined in the DiagnosticSourceEventSource, and since the contents of the IEnumerable may contain a comma, they can not be recovered reliably. A fix for this would need to be implemented on the collection side an not in PerfView.

Thanks for clarifying. Yes, I would expect this to require an issue in https://github.com/dotnet/runtime.