Windows Processor Power Management Information from Crash Dumps and ETW Traces

The starting point for my interest in this topic was the analysis of a DPC_WATCHDOG_VIOLATION bugcheck, reported in a Microsoft Q&A forum. The top of the stack at the time of the crash looked like this:

nt!KeBugCheckEx
nt!KeAccumulateTicks
nt!KiUpdateRunTime
nt!KiUpdateTime
nt!KeClockInterruptNotify
nt!HalpTimerClockInterrupt
nt!KiCallInterruptServiceRoutine
nt!KiInterruptSubDispatchNoLockNoEtw
nt!KiInterruptDispatchNoLockNoEtw
nt!KeFlushMultipleRangeTb

I recognized nt!KeFlushMultipleRangeTb as a routine that uses the Inter-Processor Interrupt (IPI) mechanism to communicate/coordinate with all of the other processors and a spin loop (including the “pause” instruction) to wait for replies. The debugger “!ipi” command showed that the processor that initiated the crash was waiting on IPI replies from 20 of the 24 (logical) processors in the system. The debugger “!running –I –t” command reported “Idle Processors:  (000000000000080c)” and could only retrieve stack traces from two processors (the processor that initiated the crash and one of the processors that had responded to the IPI and was now executing the idle loop):

amdppm!ReadIoMemRaw
amdppm!ReadGenAddr
amdppm!C2Idle
amdppm!AcpiCStateIdleExecute
nt!PpmIdleExecuteTransition
nt!PoIdle
nt!KiIdleLoop

The “CurrentThread” in the _KPRCB for all except the crash initiating processor was the “IdleThread”. The “Idle Processors:  (000000000000080c)” information identified the processors for which the “NextThread” in the _KPRCB was null.

At this point, I wanted to know a bit more about the “state” of the processors. Ultimately, the following command and result provided the reassurance that I wanted:

10: kd> dt nt!_KNODE poi(nt!KeNodeBlock) -y Deep
   +0x040 DeepIdleSet : 0xfffbff

All of the processors, except the crash initiating processor, were recorded as being in a “deep” idle state. The processor (AMD Ryzen 9 5900X 12-Core Processor) uses the AMD “chiplet” architecture, and power management is separated from the processors. My conclusion was that some problem at a hardware level prevented processors from being woken from a deep idle state and that the crash dump probably did not contain any more information that would help to more precisely identify the cause of the problem.

Extracting DPC/ISR events from the in-memory buffers of the “Circular Kernel Context Logger” ETW session and viewing them in Windows Performance Analyzer shows that all of the processors (except processor 11) stopped being “active” at nearly the same time (probably the first time the processors entered a deep idle state after the low-level/hardware problem occurred):

During the search for a method of identifying the idle state of processors, I investigated debugger extensions and Event Tracing for Windows (ETW) providers to see what information was available and how it might be retrieved from a crash dump. This topic seemed to be poorly documented, so I record my findings below.

Processor Power Management Debugger Extensions

The “Debugging Tools for Windows” help file (debugger.chm) lists just 5 processor power management commands (!ppmidle, !ppmidleaccounting, !ppmperf, !ppmperfpolicy, !ppmstate) but does not provide any information about them. The on-line Kernel-Mode Extensions help lists 8 commands (as before plus !ppmidlepolicy, !ppmlpscenarios, !ppmsettings), but only provides a terse, one sentence description of the command. The functions exported from kdexts.dll add the commands !ppm, !ppmcheck, !ppmhelp, !ppmlatency, !poperf, !platformilde and !platformidleaccounting to the list of easily discoverable commands.

The commands are probably little used outside of Microsoft, since most of them don’t work with just the public symbols available from the Microsoft symbol server. Sometimes necessary structures are simply not present in the public symbol file and sometimes the structure is present but is referred to by kdexts.dll using a “typedef” name (e.g. “nt!PPM_IDLE_STATES” rather than “nt!_PPM_IDLE_STATES”) which is not present. By “debugging the debugger”, it is sometimes possible to insert a missing underscore when necessary and thereby get an impression of the information that could be displayed.

Even when, after some coaxing, information is displayed, there is still sometimes reason to doubt its accuracy. For example, part of the output of the “!ppmidleaccounting” command is information about “IdleTime Buckets” such as:

        0 to   1ms:   46086
        1 to   2ms:   3608
        2 to   4ms:   1650
        4 to   8ms:   739
        8 to  16ms:   659
       16 to  32ms:   531
       […]

However the PlatformAccountingBucketIntervalsRundown event from the Microsoft-Windows-Kernel-Processor-Power provider (which takes its data from nt!PpmIdleIntervalLimits) suggests that the bucket intervals are:

        0 to   0.10ms
        0.10 to   0.25ms
        0.25 to   0.50ms
        0.50 to   0.75ms
        0.75 to  1ms
       1.00 to  2ms
       […]

Processor Power Management Event Tracing

There are three providers that are particularly relevant to Process Power Management (PPM) event tracing: the “System Power Provider”, “Microsoft-Windows-Kernel-Processor-Power” and “Microsoft.Windows.Kernel.Timer”.

System Power Provider

The WPR system keyword “Power” (SYSTEM_POWER_KW_GENERAL / PERF_POWER) contributes two events that are relevant to PPM: “Perf State Change” and “Idle State Change”. The “Idle State Change” event records changes between different idle “target” states (i.e. the idle state to enter when switching from the running state); the events contribute to the WPA “CPU Idle States” graph (for the “Target” state). The “Perf State Change” event records changes in CPU frequency and forms the basis of the WPA “CPU Frequency” graph; the “Microsoft-Windows-Kernel-Processor-Power” generates a similar event (ProcessorPerfStateChange) but with more information at the same time, except during “rundown”.

The WPR system keyword “IdleStates” (SYSTEM_POWER_KW_PROCESSOR_IDLE / PERF_PROCESSOR_IDLE) records transitions between running and idle states. The idle state enter event contains a wealth of information including the target C-state, the expected idle duration and wake reason and contextual information (e.g. clock owner). The IdleStates events are the main contributor to the WPA “CPU Idle States” graph (for the “Actual” state).

The actual mapping of idle state names to numbers in the raw event data is C1 → 0, C2 → 1, C3 → 2, and so on. C0 is the “running” state (i.e. not an idle state). In order to include the running state in the “CPU Idle States” graph, one is added to each idle state number and C0 (running) is assigned the value 0. The “aggregation” of the numeric state values performed by WPA when drawing the graph can make interpretation of the results a non-trivial task.

The WPR system custom keyword “0x40200000” (SYSTEM_POWER_KW_IDLE_SELECTION / PERF_IDLE_SELECTION) forms the basis of the WPA “Idle State Selection” graph. The event includes information about potential target C-states that were vetoed (along with the veto reason); typically, a veto will change the target idle state for a processor and cause an “Idle State Change” event to be generated.

There is a “Microsoft-Windows-Kernel-Processor-Power” event (BiosCStatesRundown) that provides information about the available C-states, including the latency to enter and exit the state (in microseconds) and the average power consumption (in milliwatts). On my PC, the values are:

State	Latency (μs)	Power (mW)
C1	1	1000
C2	151	200
C3	1034	200

The WPR system custom keyword “0x44000000” (SYSTEM_POWER_KW_PPM_EXIT_LATENCY / PERF_PPM_EXIT_LATENCY) records the exit latency from a “platform idle” state; “platform idle” is a lower power state for the entire System on a Chip (SoC) and is used by Modern Standby (Always on Always connected, AoAc). In addition to setting the WPR keyword, a call to the routine NtPowerInformation to set an ExitLatencySamplingPercentage value is needed before events will be generated.

Microsoft.Windows.Kernel.Timer

The “Microsoft.Windows.Kernel.Timer” events are not used by WPA and their emphasis is management of the clock; the events include ProcessorEnterDeepIdle and ProcessorExitDeepIdle.

Microsoft-Windows-Kernel-Processor-Power

Many of the “Microsoft-Windows-Kernel-Processor-Power” events are reported during the periodic execution of the PpmCheckRun DPC routine.

The WPA “Core Parking Instantaneous Concurrency” graph is mostly derived from the System Power Provider IdleStates event, but is only available if ParkNodeRundown events are also present in the trace. The word “Parking” in the graph title seems to be inappropriate: my device does not support “parking” (i.e. removing a processor from the pool of processors available for thread scheduling) and the graph shows what one might call the “Idle Processor Instantaneous Concurrency”.

The WPA “Core Parking Concurrency” graph shows essentially the same information as the “Core Parking Instantaneous Concurrency” but is derived from sampled counts of idle processors rather than exactly tracking idle transitions. The ParkNodeRecordedStats events are the source for this graph. In addition to information about the number of concurrent cores, the event also contains “concurrency histogram” information: time spent (performance counter counts) since the system booted with 0 to “n” concurrent cores (an array of n+1 values).

The WPA “Processor Performance” and “Processor Frequency” are two views of the same data: mostly DeliveredPerfChange events (if available, RecordedUtility events if not) with some context provided by ProcessorIdRundown events. Both DeliveredPerfChange and RecordedUtility carry information about both performance and frequency; on my PC the performance and frequency values (which are expressed as percentages of a nominal value) are equal. The “nominal” 100% performance/frequency values are indeed “nominal”: on my PC, the maximum performance/frequency is twice the nominal value and the y-axis of the graph covers the range 40% to 200%.

The WPA “Processor Utility” and “Processor Utilization” graphs also draw their data from RecordedUtility (plus ProcessorIdRundown) events. The RecordedUtility event includes items named BusyTime, IdleTime and DeliveredPerformance. “Processor Utilization” is calculated as:

BusyTime/(BusyTime+IdleTime)×100

“Processor Utility” is calculated as:

BusyTime/(BusyTime+IdleTime)×100×DeliveredPerformance

The DeliveredPerformance value in the event is expressed as a percentage, so if IdleTime is 0 and DeliveredPerformance is 100% then “Processor Utility” will be 10,000 (ten thousand, 10 K). This explains why the y-axis range is so large:

The meaning of the WPA “Processor Performance Tuning” graphs was not immediately clear to me. From the timing of the events, one could determine that the graphs used data from events such as ProcessorPerfStateChange, DomainPerfStateChange and QosClassPerfSelection; these events contain a (Selected)State value, which is stored as a 32-bit value in the *PerfStateChange events and as a 64-bit value in the QosClassPerfSelection evente – only when I realized that the State value was actually the value of the IA32_HWP_REQUEST_PKG MSR did the events start to make sense. Many of the other values in the events are just values broken out of IA32_HWP_REQUEST_PKG and normalized. The events report on the Hardware-Controlled Performance States (HWP); HWP is an implementation of the ACPI-defined Collaborative Processor Performance Control (CPPC). The “Epp” parameter visible in the graphs is Energy Performance Preference 

Analyzing Windows heap usage with and without ETW

 

It has been a long time since I last wanted to discover if/where a program was “leaking” heap allocations. Most programs that I developed myself just performed some task and exited; heap allocations (from all sources, including Microsoft and other third party DLLs) probably rarely exceeded a few megabytes. I coded mostly with C# (garbage collected); most heap allocations directly under my control arose from native interop and I adopted an approach of releasing memory when it was “easy” and did not obscure the main intent of the code – otherwise I “intentionally” allowed the memory to leak.

I mention the above because I am a heavy user of Event Tracing for Windows (ETW) but I had hitherto no experience of using ETW (or, indeed, any other tool) to investigate heap usage. It was only when I tried to help with a problem/question in a technical forum that I had a need to understand heap usage. The question was whether the Windows Filtering Platform API FwpmNetEventEnum unavoidably leaks heap allocations.

The first approach that came to mind was to use the User-Mode Dump Heap (UMDH) utility from the Debugging Tools for Windows kit. However, the “current” version did not seem to work. Searching the web for explanations uncovered the following quotes for other users who had encountered the problem:

According to a Microsoft employee, this is a known problem. I quote: "Yeah. It's not working and I don't know when/if it will ever be."

I also quote an email I got from a Microsoft Support guy: "Anyway, I have confirmation it is broken. The dev team owning the exe knows about it and when they can get to fixing it they will."

Fortunately older versions of UMDH still work and it quickly became apparent that FwpmNetEventEnum does leak heap allocations. Most Fwpm* routines use RPC to the Base Filtering Engine (BFE) service to perform their function. Those Fwpm* APIs that return complex data structures mostly use a [allocate(all_nodes)] attribute in the MIDL ACF (Application Configuration File) so that the data can be freed with a single call to midl_user_free; however, that attribute was not applied to the RPC routine at the core of FwpmNetEventEnum. A subsequent call to FwpmFreeMemory just frees the top-level allocation and not the additional embedded allocations.

The absence of the [allocate(all_nodes)] attribute could be confirmed with tools that dump embedded RPC data structures; one example of a heap allocation back-trace that demonstrated that complex data structures were being allocated node-by-node was:

ntdll!RtlpAllocateHeapInternal+0x80B4E

fwpuclnt!MIDL_user_allocate+0x19

RPCRT4!NdrSafeAllocate+0x47

RPCRT4!Ndr64ComplexStructUnmarshall+0x72D

RPCRT4!Ndr64EmbeddedPointerUnmarshall+0x366

RPCRT4!Ndr64UnionUnmarshall+0x2D9

RPCRT4!Ndr64ComplexStructUnmarshall+0x5F4

RPCRT4!Ndr64pPointerLayoutUnmarshallCallback+0x234

RPCRT4!Ndr64ConformantArrayUnmarshall+0x21C

RPCRT4!Ndr64TopLevelPointerUnmarshall+0x40F

RPCRT4!Ndr64TopLevelPointerUnmarshall+0x59D

RPCRT4!Ndr64pClientUnMarshal+0x2A1

RPCRT4!NdrpClientCall3+0x40C

RPCRT4!NdrClientCall3+0xEB

fwpuclnt!FwpmNetEventEnum5+0x70

Heap Snapshots

I then turned my thoughts to understanding what type of bug could have been introduced into UMDH. There are several methods of obtaining the information needed to dump heap snapshot information (including heap allocation back-traces) about a process; the routines RtlQueryProcessDebugInformation and RtlQueryHeapInformation can both independently obtain the necessary information. UMDH seems to have taken a different approach and used the routine ReadProcessMemory and a knowledge of NTDLL internal data structures to gather the information.

The failing version of UMDH seems to have started using RtlQueryHeapInformation (with an HEAP_INFORMATION_CLASS value of HeapExtendedInformation (2)) to obtain information about heap allocations, but this information does not include any data that can be used to associate the allocation with a back-trace. There is, however, a HEAP_INFORMATION_CLASS value (5, let’s name it HeapStackTraceInformation) that returns information well suited for use by UMDH (i.e. includes information about allocated heap blocks and back-traces for the allocations).

The back-traces returned by RtlQueryHeapInformation for HeapStackTraceInformation come from a different source compared to the back-traces created and store when the Global Flag FLG_USER_STACK_TRACE_DB is set. The back-traces used by RtlQueryHeapInformation are enabled and disabled by RtlSetHeapInformation (also with a HEAP_INFORMATION_CLASS value of 5) or by creating a value named “FrontEndHeapDebugOptions” under the Image File Execution Options (IFEO) key for an image; this value can be set by the Windows Performance Recorder (WPR) command “wpr -snapshotconfig heap –name […]” (“wpr -snapshotconfig heap –pid […]” effectively calls RtlSetHeapInformation).

When comparing the two versions of the back-trace information for a given allocation, they mostly just differ in the first frame:

HeapStackTraceInformation:

ntdll!RtlpAllocateHeapInternal+0x80b49:

e8528d0500      call    ntdll!RtlpHpStackTraceAddStack

 

FLG_USER_STACK_TRACE_DB:

ntdll!RtlpAllocateHeapInternal+0x809dd:

e8ac1cffff      call    ntdll!RtlpCallInterceptRoutine

The back-traces can also differ in the depth of the back-trace captured and stored (HeapStackTraceInformation can save more frames).

“wpr -singlesnapshot heap […]” uses EnableTraceEx2 to send an EVENT_CONTROL_CODE_CAPTURE_STATE to the Microsoft-Windows-Heap-Snapshot provider, using the EnableFilterDesc field of the EnableParameters parameter to select the “pids”. This causes RtlQueryHeapInformation with HeapStackTraceInformation to be executed in the target processes with the output being broken into chunks and logged into the trace session. Windows Performance Analyzer (WPA) can reassemble, analyze and display this data in a “Heap Snapshot” graph.

Heap Events

WPR provides another heap related command: “wpr -heaptracingconfig […]”. This command creates/sets another value under IFEO – namely TracingFlags. These flags enable aspects of the User Mode Global Logger (UMGL), including events generated by the WMI HeapTraceProvider; this provider generates events for individual heap events (HeapRangeCreate, HeapRangeReserve, HeapRangeRelease, HeapRangeDestroy, HeapCreate, HeapAllocation, HeapReallocation, HeapDestroy, HeapFree and more) and StackWalk back-traces can be configured for selected event types. WPA knows how to analyze and display these events too (in various graphs in the Memory category).

The instrumentation for these events is obviously embedded in many NTDLL heap routines; for the HeapAllocation event, the instrumentation is embedded close to the heap stack tracing calls:

ntdll!RtlpAllocateHeapInternal+0x80aec:

e817a30500      call    ntdll!RtlpLogHeapAllocateEvent

If a process was started without heap tracing enabled via IFEO, heap tracing can still be enabled by directly setting the heap tracing bit in the _PEB.TracingFlags field (perhaps via a debugger); there does not seem to be any API that performs this function.

Intel Processor Trace (IPT) under Windows

My interest in IPT under Windows has been piqued more than once but, until now, my judgement of the effort versus benefit of interpreting IPT data tended to a “not worth it” decision: identifying and displaying the individual IPT packets seemed straightforward enough but interpreting the Taken/Not-taken (TNT) bits would require a disassembler and the binary code and load addresses of all the executable files that might have been executed. Mentions of IPT tracing and trace analysis found in the Web often mention very large volumes of trace data and very long trace analysis times.

The event that prompted a more detailed consideration of the effort required to develop a simple (and therefore slow) tool to analyse very short IPT traces was the discovery that Windows Performance Recorder (WPR) can be configured to cause “IPT” events to be generated as an accompaniment to kernel events. The Windows Performance Recorder Profile (WPRP) schema (https://docs.microsoft.com/en-us/windows-hardware/test/wpt/wprcontrolprofiles-schema) includes a description of the “HardwareCounter” element which can contain elements such as “LastBranch” (for Last Branch Recording (LBR)), “Counters” (for capturing Performance Monitoring Counters (PMC)) and “ProcessorTrace” (for Intel Processor Tracing (IPT)).

The configuration of ProcessorTrace is simple: one just has to specify three items:

1. The “CodeMode” for the trace (user, kernel or user plus kernel).
2. The (maximum) “BufferSize” of the IPT trace data (chosen from 4, 8, 16 or 32 kilobytes).
3. A list of the kernel “Events” that cause a corresponding IPT event to be generated. The events can be chosen from the “SystemStackEnumeration” which is the list of event names that can be used in configuring stack traces for the system provider.

One thing that is missing is an equivalent of the “CustomStack” element for defining custom events, since not all of the kernel events are included in SystemStackEnumeration. A sample configuration could look like this:

<HardwareCounter Id="Perf">

  <ProcessorTrace>

    <BufferSize Value="4" />

    <CodeMode Value="Kernel" />

    <Events>

      <Event Value="SystemCallExit" />

    </Events>

  </ProcessorTrace>

</HardwareCounter>

 

Starting “small” (smallest buffer size and a single code mode) might be advisable until one has acquired experience in the analysis and interpretation of the data.

Out-of-the-box, there are no MOF classes describing most of the performance events; I added the following definitions for IPT on my system with the “mofcomp” utility:

[dynamic: ToInstance, Guid("{ff1fd2fd-6008-42bb-9e75-00a20051f3be}"), EventVersion(2), DisplayName("IntelProcessorTrace")]

class IPT_V2 : MSNT_SystemTrace
{
}; 

[dynamic: ToInstance, EventType{32}, EventTypeName{"ProcessorTrace"}]
class IPT_Event : IPT_V2
{
    [WmiDataId(1), read] uint64 EventTimeStamp;
    [WmiDataId(2), read] uint32 Process;
    [WmiDataId(3), read] uint32 Thread;
    [WmiDataId(4), read, format("x")] uint64 IptOption;
    [WmiDataId(5), read] uint32 TraceSize;
    [WmiDataId(6), read] uint32 TracePosition;
};

The actual trace data follows immediately after this header; I could not think of a way to include the variable length array of bytes in the MOF class definition.

The first three members are identical in meaning to a kernel stack trace event. A type for the IptOption value is available as a public type in the ipt.sys driver; Windows debuggers display it thus:

0:000> dt ipt!_IPT_OPTION
   +0x000 TraceMode        : Pos 0, 4 Bits
   +0x000 TimeMode         : Pos 4, 4 Bits
   +0x000 MTCFreq          : Pos 8, 4 Bits
   +0x000 CycThresh        : Pos 12, 4 Bits
   +0x000 BufferSize       : Pos 16, 4 Bits
   +0x000 TraceSessionMode : Pos 20, 3 Bits
   +0x000 TraceChild       : Pos 23, 1 Bit
   +0x000 TraceCodeMode    : Pos 24, 4 Bits
   +0x000 Reserved2        : Pos 28, 4 Bits
   +0x004 Reserved3        : Uint4B
   +0x000 Value            : Uint8B 

The TraceSize is the size of the trace data; if the size is less than the configured size, then the “entire” trace is available (all trace data from the last context switch until the triggering event occurred). If TraceSize is equal to the configured “BufferSize” then the trace has probably wrapped and “TracePosition” is the point in the (circular) buffer at which the next packet would have been written; one has to search the buffer in a circular fashion for a PSB (Packet Stream Boundary) packet, starting from the TracePosition.

By including “Loader”keyword events in a WPR trace (which enables loaded modules to be identified, along with their load address), one seems “in good shape” to interpret the IPT trace.

A disassembler is needed to interpret the IPT trace and fortunately one is readily available: the one used by the Windows debuggers, namely the Disassemble method of the IDebugControl interface. The disassembler is needed to identify relevant instructions (e.g. conditional branches) and instruction lengths. The “Disassemble” method does much more than this, formatting the instruction as a string and performing symbol look-up for memory references, so it is slow but it does the job and obviates the need to develop a purpose oriented replacement.

In a typical trace, code from many executable files may appear and the IDebugClient/IDebugControl interfaces is probably not well suited to simultaneously opening several separate executable files. “Fortunately”, I encountered another problem with this approach and the same “solution” resolved both problems.

This code is taken from the executable file; because it contains an indirect control transfer, a TIP (Target IP) would be needed in the IPT trace:

tcpip!TcpDeliverDataToClient+0x119:
call qword ptr [tcpip!_imp_KeAcquireSpinLockAtDpcLevel (00000001`c02331e8)]
nop  dword ptr [rax+rax]
cmp  r14d,0C000021Bh 

However no TIP was present and it turned out that the code in memory that was actually executed looks like this (direct control transfer):

tcpip!TcpDeliverDataToClient+0x119:
mov  r10,qword ptr [tcpip!_imp_KeAcquireSpinLockAtDpcLevel (fffff803`590d31e8)]
call nt!KeAcquireSpinLockAtDpcLevel (fffff803`534a2490)
cmp  r14d,0C000021Bh 

Import Optimization (https://techcommunity.microsoft.com/t5/windows-kernel-internals-blog/mitigating-spectre-variant-2-with-retpoline-on-windows/ba-p/295618) had been applied when building the executable and, whilst there is obviously sufficient metadata in the executable file to recognize and emulate the code modifications, it would be difficult to integrate this into the simple use of the disassembler.

The “solution” was to use a “dump” of the process (or a “live dump” of the kernel) to perform the analysis. This simplifies many things but also means that a standalone ETW (Event Tracing for Windows) file is not enough for an analysis with my simple tool (a dump is needed too).

The “conciseness” of the IPT trace data means that it is not easy to “check” whether an analysis is proceeding correctly. One of my many mistakes was in incorrectly handling “Indirect Transfer Compression for Returns” (the uncompressed cases), but “RET compression” was a big help in identifying problems: if a RET was compressed, then the Taken/Not-taken bit should be set and if it is clear then one knows that something has gone wrong. Another hint is if the “recorded” code path does not seem plausible; this is not always easy to judge, but I often found that my tool was analyzing the routine “KeBugCheckEx” – something that had patently not happened during the trace capture.

My “use case” for IPT tracing is as an additional aid in debugging/troubleshooting tricky/interesting problems. For this type of tracing to be useful, one needs to identify kernel events that occur after the code of interest has been executed and whose IPT data might include the path taken. The limited set of events in SystemStackEnumeration (lacking, for example, network events) is a hindrance, but the undocumented API to set additional custom events is relatively easy to deduce. IPT trace data attached to the “CSwitch” event is often useful; some traces are very short (a context switch from idle) and are useful for testing the TNT interpreter and some others are useful “backstops” for data gathering (especially if the context switch is the result of a natural “break” in execution, such as entering a wait state).

\Device\IPT IOCTL Interface

IPT can be used separately from ETW: the ipt.sys driver makes certain IPT operations available via an IOCTL style interface. This interface is not documented, but the ipt.sys driver is small and “straightforward”, so many of the features of the interface can be deduced. As someone who is almost exclusively interested in short IPT, it is a relief that the interface supports some of the IPT filtering mechanisms – most importantly filtering by IP (Instruction Pointer).

The current (undocumented and probably still evolving) interface allows IPT tracing to be enabled for a process and IP filtering to be configured per thread. Once tracing has been enabled for a process (which enables tracing on all threads in the process), tracing of individual threads can be suspended and resumed and IP filtering can be applied to individual threads. Threads created after tracing has started inherit the tracing options set for the process but start without any IP filtering.

I am often interested in tracing the path through short sections of code in service processes, where the thread which will execute the code cannot easily be predicted and might even be a newly created thread. I wanted to avoid “invading” the process to be traced (by attaching a “debugger”), but that is the only standard way of being informed of (and partially controlling) thread creation in a process. Initially, I thought that this would be simple: just receive the debug events, apply the IPT IP filter to any newly created threads and then resume the target. However applying an IPT IP filter to a thread that has just been created and is paused at the create thread debug event has no effect – it is necessary to arrange for the thread to proceed to the “LdrInitializeThunk” routine before applying the filter.

Most of the IPT tracing configurable via IOCTL traces to circular buffers; these buffers can be large and, with judicious filtering, they might not need to wrap. There is one operation that writes the trace data directly to a file, ensuring a complete trace; this operation just traces the user mode behaviour of a process and does not support IP filtering.

Summary

I am often interested with problems related to networking (for example, a potential minor problem in the Windows Filtering Platform, described in an earlier posting) and the frequently used troubleshooting tools are event tracing (including network packet) and user-mode debugging. Kernel debugging is possible but I use it only very occasionally (partly because disturbing the timing of things in the debugger disturbs the whole evolution of the debugging scenario). IPT tracing will hopefully be useful, when it can be applied. Often the “transmit” side of communication occurs in a predictable process (and a process for which a “handle” can be obtained) and here process based tracing can be effectively deployed. However, the “receive” side can occur in any context/process and I hope that combining ETW and IPT will help there. There are also common scenarios where the “transmissions” originate from the “System” process (e.g. SMB traffic) and the IOCTL interface, which uses handles rather than process ids to identify the target, can’t be used there.