Kernel tracing of Registry events and high CPU

Jun 2, 2011 at 6:57 PM

I’ve been using TraceEvent to monitor File, Network and Process kernel events. This has been working great with CPU utilization of my process always well below 2%. However, if I add Registry to the kernel trace, CPU utilization suddenly jumps to a steady 90%+.

I’ve done some rate comparisons and there doesn’t appear to be any reason for the CPU surge:

60 seconds of monitoring File, Network and Process:  Total events: 838,484, average CPU utilization: 0.5%

60 seconds of monitoring just Registry:  Total Events: 226,426, average CPU utilization: 92%

For purposes of my testing, I’ve eliminated all event processing on my end, I’m just receiving the events with:

ETWTraceEventSource t = new ETWTraceEventSource("NT Kernel Logger", TraceEventSourceType.Session);

Any ideas?

Jun 3, 2011 at 6:01 PM

I notice that you are using 'Session' rather than a file as your event source.   This blurs data colleciton and processing so we don't know which is to blame. 

I would recommend that at least for diagnostic purposes, you break them apart (collect data to and ETL file and then do you processing).  This will allow you to determine how much data is actually being generate (the size of hte ETL file), and will also determine if collection or processing is to blame (it is likely to be processing).   If so, you can use PerfMonitor to take a profile of the processing part (you can't do this for your real-time session because perfMonitor uses the kernel provider and only one is allowed to be active at any one time).  

Aug 9, 2011 at 4:58 PM
Edited Aug 9, 2011 at 5:02 PM


Since last writing to you about this issue, I’ve taken your direction and have been going through my
code trying to find the source of my performance problems, but no luck.  My primary concern is no longer CPU but rather Memory usage.  I’ve distilled the code
necessary to repro the memory behavior to the following crude example:

    class Program
    {
        static void Main(string[] args)
        {
            Console.WriteLine("strating etw session");
            ETWTraceEventSource etw = new ETWTraceEventSource("NT Kernel Logger", TraceEventSourceType.Session);
            etw.Kernel.FileIoWrite += new Action<FileIoReadWriteTraceData>(Kernel_FileIoWrite);
            etw.Kernel.RegistrySetValue += new Action<RegistryTraceData>(Kernel_RegistrySetValue);
            etw.Process();
        }

        static void Kernel_RegistrySetValue(RegistryTraceData obj)
        {
            Console.WriteLine(obj.ValueName);
        }

        static void Kernel_FileIoWrite(FileIoReadWriteTraceData obj)
        {
            Console.WriteLine(obj.EventName);
        }
    }

This simple example will slowly and continually eat up memory (private working set).  In my particular
scenario, my real application needs to run for long periods of time and the memory consumption
behavior becomes a problem after an hour or so.  I have to completely close and restart my app to
resolve the issue.

Any thoughts?  Do you still think that I should use the profiler on this simple example to determine the problem?

And, thanks again for all of your work!!  It’s really great being able to access all of this event data in
.net!

Developer
Aug 11, 2011 at 3:42 PM

I think I know what the problem is.  I will fix in the master copy, but you should fix it in your copy.

What is likely growing is the KernelTraceEventParserState.fileIDToName table as well as the threadIDToProcess table.

These tables allow numbers used to identify a file, or a registry key, or a thread to a more useful value (like a string name).

Currently entries only enter this table (they are never deleted)  This if fine for finite logs, but you have the infinite case.

You need to purge old entries that you believe are no longer needed (you will never look up that ID again).  

For threads and registry keys, there is an obvious 'close' event that can be used to remove the entry.  For files it is

not so clear, but maybe that one really is not the problem (it is likely it is the threads table that is growin most quickly,

the file ID table shoudl grow only as NEW files are touched (although this can also be infinite)