microsoft / perfview

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

RegistryKCBRundownEnd Event is not raised in realtime TraceEventSession #928

Open philippkratzer opened 5 years ago

philippkratzer commented 5 years ago

No RegistryKCBRundownEnd Events are raised in TraceEventSessions.

When I start a TraceEventSession using the following code snippet:

using (var session = new TraceEventSession("MonitorKernelAndClrEventsSession"))
{
    session.EnableKernelProvider(KernelTraceEventParser.Keywords.Process | KernelTraceEventParser.Keywords.Registry);
    session.Source.Kernel.RegistryKCBRundownEnd += (RegistryTraceData obj) => { Console.WriteLine("Event was raised"); };
    session.Source.Process();
}

The event is never raised.

When I create an ETL trace file using the following code snippet:

using (var session = new TraceEventSession("MonitorKernelAndClrEventsSession", "etl.etl"))
{
    session.EnableKernelProvider(KernelTraceEventParser.Keywords.Process | KernelTraceEventParser.Keywords.Registry);
    Thread.Sleep(10000);
}

Interestingly, the details shown by xperf (xperf -i .\etl.etl -a tracestats -detail) show that there are rundown events in the ETL file:

Type Level Version                        Count       TotalSize  Name
---- ----- -------                   ---------- ---------------  ---------------------------------------
0x19  0x00 0x0002                          5293         1120614  Registry: Kcb: End Rundown

Even more surprising is that the ETWReloggerTraceEventSource raises the desired event when opening this ETL trace:

using (var relogger = new ETWReloggerTraceEventSource("etl.etl", "out.etl"))
{
    relogger.Kernel.RegistryKCBRundownEnd += (RegistryTraceData obj)=> { Console.WriteLine("Event was raised"); };
}

From my understanding, there is an issue while handling events in "realtime sessions". The desired events are not fired, but they seem to be in the ETL trace when logged to a file.

JamesLear92 commented 4 years ago

This was driving me nuts as I thought I was doing something wrong. This still isn't fixed EDIT: I've looked into this a little further, and I think the issue is that the RegistryKCBRundown events only occur at the end of a session and this is captured when logging to a file but since the session contains the event handlers that would process them in a live trace, the handlers are lost when the session ends. I think.

I have tried to work around this by logging to a file for ~2 seconds, and then reading from the file but this can certainly miss events. I hope someone works out a solution for this.

Is it possible to have a non-live capture, but saving to memory rather than file?

JamesLear92 commented 4 years ago

Not sure if you still need this functionality, but I did find a way in the end. The RegistryKCBRundown event does only trigger when the session is ended, so I did the following to get those events that are right at the end:

using System;
using Microsoft.Diagnostics.Tracing.Parsers;
using Microsoft.Diagnostics.Tracing.Session;
using Microsoft.Diagnostics.Tracing.Parsers.Kernel;
using System.Diagnostics;
using System.Threading;
using System.Collections.Generic;
using System.Linq;
using System.Text.RegularExpressions;
using System.Collections.Concurrent;

namespace RegistryEventCapture
{
    class Program
    {
        static void Main(string[] args)
        {

            var MonitorTimeInSeconds = 0.2;
            var dictionary = new Dictionary<ulong, string>();
            var stop = false;
            var OwnPid = Process.GetCurrentProcess().Id;
            while (!stop)
            {
                List<CustomEventItem> eventList = new List<CustomEventItem>();
                var session = new TraceEventSession("MonitoringRegistries", null);
                session.EnableKernelProvider(KernelTraceEventParser.Keywords.Registry);
                session.Source.Kernel.RegistryKCBRundownEnd += delegate (RegistryTraceData data)
                {
                    if (dictionary.ContainsKey(data.KeyHandle))
                        dictionary[data.KeyHandle] = data.KeyName;
                    else
                        dictionary.Add(data.KeyHandle, data.KeyName);
                };
                session.Source.Kernel.RegistryCreate += (RegistryTraceData data) => { if (data.ProcessID != OwnPid) eventList.Add(new CustomEventItem(data)); };
                session.Source.Kernel.RegistryDelete += (RegistryTraceData data) => { if (data.ProcessID != OwnPid) eventList.Add(new CustomEventItem(data)); };
                session.Source.Kernel.RegistrySetValue += (RegistryTraceData data) => { if (data.ProcessID != OwnPid) eventList.Add(new CustomEventItem(data)); };
                session.Source.Kernel.RegistryDeleteValue += (RegistryTraceData data) => { if (data.ProcessID != OwnPid) eventList.Add(new CustomEventItem(data)); };
                session.Source.Kernel.RegistryEnumerateKey += (RegistryTraceData data) => { if (data.ProcessID != OwnPid) eventList.Add(new CustomEventItem(data)); };
                session.Source.Kernel.RegistryEnumerateValueKey += (RegistryTraceData data) => { if (data.ProcessID != OwnPid) eventList.Add(new CustomEventItem(data)); };
                session.Source.Kernel.RegistryOpen += (RegistryTraceData data) => { if (data.ProcessID != OwnPid) eventList.Add(new CustomEventItem(data)); };
                session.Source.Kernel.RegistryClose += (RegistryTraceData data) => { if (data.ProcessID != OwnPid) eventList.Add(new CustomEventItem(data)); };
                session.Source.Kernel.RegistryQueryValue += (RegistryTraceData data) => { if (data.ProcessID != OwnPid) eventList.Add(new CustomEventItem(data)); };
                session.Source.Kernel.RegistryQueryMultipleValue += (RegistryTraceData data) => { if (data.ProcessID != OwnPid) eventList.Add(new CustomEventItem(data)); };
                session.Source.Kernel.RegistrySetInformation += (RegistryTraceData data) => { if (data.ProcessID != OwnPid) eventList.Add(new CustomEventItem(data)); };

                using (session)
                {
                    var timer = new Timer(delegate (object state)
                    {
                        session.Stop();
                    }, null, (int)(MonitorTimeInSeconds * 1000), Timeout.Infinite);
                    session.Source.Process();
                }

                foreach (var eventItem in eventList.OrderBy(x => x.EventIndex).ToList())
                {
                    try
                    {
                        if (eventItem.KeyHandle != 0 && dictionary.ContainsKey(eventItem.KeyHandle))
                        {
                            eventItem.FullName = dictionary[eventItem.KeyHandle];
                            if (!string.IsNullOrWhiteSpace(eventItem.KeyName))
                                eventItem.FullName += "\\" + eventItem.KeyName;
                            if (!string.IsNullOrWhiteSpace(eventItem.ValueName))
                                eventItem.FullName += "\\" + eventItem.ValueName;
                        }
                        eventItem.FullName = Regex.Replace(eventItem.FullName, @"\\REGISTRY\\MACHINE", "HKEY_LOCAL_MACHINE", RegexOptions.IgnoreCase);
                        eventItem.FullName = Regex.Replace(eventItem.FullName, @"\\REGISTRY\\USER", "HKEY_USERS", RegexOptions.IgnoreCase);
                        QueuedConsole.WriteLine(string.Format("{0} - {1} - {2} - PID: {3} Process: {4}", eventItem.TimeStamp, eventItem.EventName, eventItem.FullName, eventItem.ProcessID, eventItem.ProcessName));
                    }
                    catch
                    {
                        Debugger.Break();
                    }
                }
                Console.CancelKeyPress += new ConsoleCancelEventHandler((object sender, ConsoleCancelEventArgs cancelArgs) =>
                {
                    session.Stop();
                    session.Dispose();        // Note that this causes Process() to return.  
                    cancelArgs.Cancel = true; // This says don't abort, since Process() will return we can terminate nicely.
                    stop = true;
                });
                session.Stop();
                session.Dispose();
            }
        }
        public static class QueuedConsole
        {
            private static BlockingCollection<string> m_Queue = new BlockingCollection<string>();

            static QueuedConsole()
            {
                var thread = new Thread(() => { while (true) Console.WriteLine(m_Queue.Take()); });
                thread.IsBackground = true;
                thread.Start();
            }

            public static void WriteLine(string value)
            {
                m_Queue.Add(value);
            }
        }
    }
    class CustomEventItem
    {
        public DateTime TimeStamp { set; get; }
        public string EventName { set; get; }
        public string KeyName { set; get; }
        public string ValueName { set; get; }
        public int ProcessID { set; get; }
        public string ProcessName { set; get; }
        public string UserInfo { set; get; }
        public int EventIndex { set; get; }
        public ulong KeyHandle { set; get; }
        public string FullName { set; get; }
        public int State { set; get; }

        public CustomEventItem(RegistryTraceData data)
        {
            this.TimeStamp = data.TimeStamp;
            this.EventName = data.OpcodeName;
            this.KeyName = data.KeyName;
            this.ValueName = data.ValueName;
            this.ProcessID = data.ProcessID;
            this.ProcessName = data.ProcessName;
            this.UserInfo = data.EventTypeUserData?.ToString();
            this.EventIndex = (int)data.EventIndex;
            this.KeyHandle = data.KeyHandle;
            this.FullName = data.KeyName + data.ValueName;
            this.State = data.Status;
        }
    }
}

What this does is configure the event handlers on the source, and then triggers the KcbRunDown events by calling "Stop()" on the session but not disposing; "StopProcessing()" on the source does not trigger these events.

Once it's got a list of the events, and has loaded the KeyNames into a dictionary using the KeyHandles, it loops over the events and adds the full key name in. I've got a threaded console method just so that the output can queue and not prevent the entire method from looping.

The CustomEventItem class is needed as the events lose their data once the callback is complete, so it needs to be captured.

The session then is disposed and the loop continues, and recreates it. This is because "Process()" can't be called more than once on a source which is real time.

I'm sure there is a nicer way of doing this, but I don't know.

CyberzSentry commented 4 years ago

Same thing goes for the "FileIOFileRundown" events.