Wednesday, 17 July 2024

Windows high-resolution time stamps (QueryPerformanceCounter)

The Microsoft article “Acquiring high-resolution time stamps” provides a good deal of useful information about high-resolution timing under Windows and Simon Anciaux provided the source code of a routine that matches the Windows 11 QueryPerformanceCounter routine (QueryPerformanceFrequency returning 10mhz bug).

Nonetheless, there is more that can be said and that might provide additional reassurance that one’s understanding of high-resolution timing is accurate.

There is a Windows kernel variable named HalpRegisteredTimers that points to a linked list of registered timers; the routine that registers the timers is passed a pointer to a TIMER_INITIALIZATION_BLOCK (whose format is defined in file nthalext.h). On my PC, 8 timers appear in the list and one can infer some interesting values from the information in the calls to register timers.

The KnownType values are members of the enum KNOWN_TIMER_TYPE (also defined in nthalext.h). In case the names are not immediately recognizable, here are some brief descriptions:

TimerProcessor: the processor Time-Stamp Counter (TSC).

TimerART: the processor Always Running Timer, perhaps mostly commonly encountered in conjunction with “Intel Processor Trace”.

TimerApic: Advanced Programmable Interrupt Controller (APIC).

TimerAcpi: Advanced Configuration and Power Interface (ACPI) power management timer.

TimerCmosRtc: the Real Time Clock (RTC).

TimerHpet: High Precision Event Timer (HPET)

KnownType

Identifier

CounterBitWidth

CounterFrequency

Capabilities

TimerProcessor

0

64

1992000000
(24000000
× 166 / 2)

1991998774
1991998859

TIMER_PER_PROCESSOR
TIMER_COUNTER_READABLE
TIMER_COUNTER_WRITABLE
TIMER_SUPPORTS_ADVANCED_QUERY

TimerART

0

64

24000000

24000038
24000039

TIMER_PER_PROCESSOR
TIMER_COUNTER_READABLE
TIMER_ALWAYS_ON
TIMER_AUXILIARY

TimerApic

0

32

187500
(24000000 / 128)

187500
187497

TIMER_PER_PROCESSOR
TIMER_COUNTER_READABLE
TIMER_ONE_SHOT_CAPABLE
TIMER_PERIODIC_CAPABLE
TIMER_GENERATES_INTERNAL_INTERRUPTS

TimerAcpi

0

24

3579545

TIMER_COUNTER_READABLE

TimerCmosRtc

0

64

2048

TIMER_PSEUDO_PERIODIC_CAPABLE
TIMER_ONE_SHOT_CAPABLE
TIMER_SINGLE_INIT

TimerHpet

0

32

24000000

TIMER_COUNTER_READABLE

TimerHpet

1

31

24000000

TIMER_PSEUDO_PERIODIC_CAPABLE
TIMER_ONE_SHOT_CAPABLE
TIMER_PERIODIC_CAPABLE
TIMER_GENERATES_8259_INTERRUPTS

TimerHpet

2

31

24000000

TIMER_PSEUDO_PERIODIC_CAPABLE
TIMER_ONE_SHOT_CAPABLE
TIMER_GENERATES_8259_INTERRUPTS

 

When registering the timers on my PC, the CounterFrequency of the TimerProcessor, TimerART and TimerApic timers is specified as zero; actual values are determined by comparing these timers to another timer whose nominal frequency is considered to be reliable. Windows has a preference list of which timer should be used as a reference and the first choice is TimerAcpi; on my PC, this timer is available and is used. The timers are compared over a period of one eighth of a second (125 milliseconds).

Section 19.7.3 (“Determining the Processor Base Frequency”) of Intel 64 and IA-32 Architectures Software Developer's Manual Volume 3 contains a table of “Nominal Core Crystal Clock Frequency”; for my PC, the value is 24 MHz. The CPUID instruction with EAX set to 15H (Time Stamp Counter and Nominal Core Crystal Clock Information Leaf) returns the values 2 as the denominator of the TSC/”core crystal clock” ratio and 166 as the numerator of the TSC/”core crystal clock” ratio; the nominal frequency of the core crystal clock in Hz is not enumerated on my CPU.

These values allow a nominal counter frequency for TimerProcessor to be calculated (1992000000 Hz). The other values in the table above (1991998774 and 1991998859) are the results of two runs of the measuring process against the ACPI PM timer.

TimerART runs at the “Nominal Core Crystal Clock Frequency” (24000000 Hz); again, the other values in the table above (24000038 and 24000039) are the results of two runs of the measuring process against the ACPI PM timer. Although there is no instruction to read the ART (Windows determines its value by evaluating (__rdtscp() - __rdmsr(IA32_TSC_ADJUST)) * CPUID.15H:EAX[31:0] / CPUID.15H:EBX[31:0]), it is measured separately.

I have assumed that the APIC timer also has a nominal frequency of 24 MHz and a divider of 128, giving a nominal frequency of 187500 Hz; the other values (187500 and 187497) are the measurement results.

In the simplest case, the value returned by QueryPerformanceCounter is the result of executing the following calculations:

_umul128(__rdtscp(out _), HypervisorSharedUserData.Factor, out ulong qpc);

qpc += HypervisorSharedUserData.Bias;

qpc += SharedUserData.QpcBias;

qpc >>= SharedUserData.Qpc.QpcShift;

SharedUserData is intended as a reference to the KUSER_SHARED_DATA structure; HypervisorSharedUserData is intended as the reference returned by the call NtQuerySystemInformation(SystemHypervisorSharedPageInformation, …); HypervisorSharedUserData.Bias is zero and HypervisorSharedUserData.Factor is the integral result of evaluating:

CpuHz is the measured TimerProcessor frequency and the evaluation is performed as a _udiv128 style calculation.

Auxiliary Counter routines

Windows has a group of functions with names including the string “AuxiliaryCounter”, such as QueryAuxiliaryCounterFrequency, ConvertPerformanceCounterToAuxiliaryCounter. These functions are related to the timer with the capability TIMER_AUXILIARY, if such a timer is present; on my PC, this is TimerART. The documentation for the group of functions is not very informative; I could only find one use of the functions on my PC: in file IntcAudioBus.sys (FileDescription: “Intel® Smart Sound Technology (Intel® SST) Bus”).

TSC synchronization

The Microsoft-Windows-HAL Event Tracing for Windows provider records the synchronization of the TSC values between the processors. Here is a condensed summary from a synchronization run:

The processor cycle counter on processor 1 has been probed by processor 0. A counter delta of -199 was detected. The approximate communication delay between these processors was detected to be 508.

[…]

The processor cycle counter on processor 0 was synchronized against processor 4 using an adjustment of 94 cycles on attempt 0. This resulted in a delta of -13 cycles.

The processor cycle counter on processor 1 was synchronized against processor 0 using an adjustment of 342 cycles on attempt 0. This resulted in a delta of 68 cycles.

[…]

The processor cycle counter on processor 1 has been probed by processor 0. A counter delta of 10 was detected. The approximate communication delay between these processors was detected to be 500.

[…]

The processor's cycle counters have been successfully synchronized from processor 0 within acceptable operating thresholds. The maximum positive delta detected was 10 and the maximum negative delta was -11. Synchronization executed for 7773 microseconds.

If the processors cycle counters can be synchronized to within “acceptable operating thresholds” then it should be impossible for a thread, rescheduled on a different processor, to detect a backwards step in the TSC values.

Tuesday, 30 January 2024

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.