Kernel Event Tracing

Various components of the Windows kernel and several core device drivers are instrumented to record trace data of their operations for use in system troubleshooting. They rely on a common infrastructure in the kernel that provides trace data to the user-mode Event Tracing for Windows (ETW) facility. An application that uses ETW falls into one or more of three categories:

• Controller. A controller starts and stops logging sessions and manages buffer pools. Example controllers include Reliability and Performance Monitor (see the EXPERIMENT: Tracing TCP/IP Activity with the Kernel Logger section, later in this section) and XPerf from the Windows Performance Toolkit (see the EXPERIMENT: Monitoring Interrupt and DPC Activity section, earlier in this chapter).

• Provider. A provider defines GUIDs (globally unique identifiers) for the event classes it can produce traces for and registers them with ETW. The provider accepts commands from a controller for starting and stopping traces of the event classes for which it’s responsible.

• Consumer. A consumer selects one or more trace sessions for which it wants to read trace data. Consumers can receive the events in buffers in real time or in log files.

Windows includes dozens of user-mode providers, for everything from Active Directory to the Service Control Manager to Explorer. ETW also defines a logging session with the name NT Kernel Logger (also known as the kernel logger) for use by the kernel and core drivers. The providers for the NT Kernel Logger are implemented by ETW code in Ntoskrnl.exe and the core drivers.

When a controller in user mode enables the kernel logger, the ETW library (which is implemented in \Windows\System32\Ntdll.dll) calls the NtTraceControl system function, telling the ETW code in the kernel which event classes the controller wants to start tracing. If file logging is configured (as opposed to in-memory logging to a buffer), the kernel creates a system thread in the system process that creates a log file. When the kernel receives trace events from the enabled trace sources, it records them to a buffer. If it was started, the file logging thread wakes up once per second to dump the contents of the buffers to the log file.

Trace records generated by the kernel logger have a standard ETW trace event header, which records time stamp, process, and thread IDs, as well as information on what class of event the record corresponds to. Event classes can provide additional data specific to their events. For example, disk event class trace records indicate the operation type (read or write), disk number at which the operation is directed, and sector offset and length of the operation.

Some of the trace classes that can be enabled for the kernel logger and the component that generates each class include the following:

• Disk I/O. Disk class driver

• File I/O. File system drivers

• File I/O Completion. File system drivers

• Hardware Configuration. Plug and Play manager (See Chapter 9 in Part 2 for information on the Plug and Play manager.)

• Image Load/Unload. The system image loader in the kernel

• Page Faults. Memory manager (See Chapter 10 in Part 2 for more information on page faults.)

• Hard Page Faults. Memory manager

• Process Create/Delete. Process manager (See Chapter 5 for more information on the process manager.)

• Thread Create/Delete. Process manager

• Registry Activity. Configuration manager (See The Registry section in Chapter 4 for more information on the configuration manager.)

• Network TCP/IP. TCP/IP driver

• Process Counters. Process manager

• Context Switches. Kernel dispatcher

• Deferred Procedure Calls. Kernel dispatcher

• Interrupts. Kernel dispatcher

• System Calls. Kernel dispatcher

• Sample Based Profiling. Kernel dispatcher and HAL

• Driver Delays. I/O manager

• Split I/O. I/O manager

• Power Events. Power manager

• ALPC. Advanced local procedure call

• Scheduler and Synchronization. Kernel dispatcher (See Chapter 5 for more information about thread scheduling)

You can find more information on ETW and the kernel logger, including sample code for controllers and consumers, in the Windows SDK.

EXPERIMENT: Tracing TCP/IP Activity with the Kernel Logger

To enable the kernel logger and have it generate a log file of TCP/IP activity, follow these steps:

1. Run the Performance Monitor, and click on Data Collector Sets, User Defined.

2. Right-click on User Defined, choose New, and select Data Collector Set.

3. When prompted, enter a name for the data collector set (for example, experiment), and choose Create Manually (Advanced) before clicking Next.

4. In the dialog box that opens, select Create Data Logs, check Event Trace Data, and then click Next. In the Providers area, click Add, and locate Windows Kernel Trace. In the Properties list, select Keywords(Any), and then click Edit.

   

5. From this list, select only Net for Network TCP/IP, and then click OK.

   

6. Click Next to select a location where the files are saved. By default, this location is C:\Perflogs\<User>\experiment\, if this is how you named the data collector set. Click Next, and in the Run As edit box, enter the Administrator account name and set the password to match it. Click Finish. You should now see a window similar to the one shown here:

   

7. Right-click on “experiment” (or whatever name you gave your data collector set), and then click Start. Now generate some network activity by opening a browser and visiting a web site.

8. Right-click on the data collector set node again, and then click Stop.

9. Open a command prompt, and change to the C:\Perflogs\experiment\00001 directory (or the directory into which you specified that the trace log file be stored).

10. Run tracerpt, and pass it the name of the trace log file:

    tracerpt DataCollector01.etl –o dumpfile.csv –of CSV

11. Open dumpfile.csv in Microsoft Excel or in a text editor. You should see TCP and/or UDP trace records like the following:

TcpIp	SendIPV4	0xFFFFFFFF	1.28663E+17	0	0	1992	1388	157.54.86.28	172.31.234.35	80	49414	646659	646661
UdpIp	RecvIPV4	0xFFFFFFFF	1.28663E+17	0	0	4	50	172.31.239.255	172.31.233.110	137	137	0	0x0
UdpIp	RecvIPV4	0xFFFFFFFF	1.28663E+17	0	0	4	50	172.31.239.255	172.31.234.162	137	137	0	0x0
TcpIp	RecvIPV4	0xFFFFFFFF	1.28663E+17	0	0	1992	1425	157.54.86.28	172.31.234.35	80	49414	0	0x0
TcpIp	RecvIPV4	0xFFFFFFFF	1.28663E+17	0	0	1992	1380	157.54.86.28	172.31.234.35	80	49414	0	0x0
TcpIp	RecvIPV4	0xFFFFFFFF	1.28663E+17	0	0	1992	45	157.54.86.28	172.31.234.35	80	49414	0	0x0
TcpIp	RecvIPV4	0xFFFFFFFF	1.28663E+17	0	0	1992	1415	157.54.86.28	172.31.234.35	80	49414	0	0x0
TcpIp	RecvIPV4	0xFFFFFFFF	1.28663E+17	0	0	1992	740	157.54.86.28	172.31.234.35	80	49414	0	0x0