TotalProcessorTime differs between Windows 10 and Windows 11

Question

For our applications we use the Process.GetCurrentProcess().TotalProcessorTime to determine how much CPU is used for actions calls.

When an action takes 1 second to execute and only performs cpu operations, we except 1 second of cpu time.

For Windows 10 this works as expected, for Windows 11 the cpu usage is always 30/50% lower.

This behavior applies to .net framework and .net 6 applications

Below is a test application to reproduce the problem.

using System;
using System.Diagnostics;
using System.Threading.Tasks;

_ = Task.Run(() => ConsumeCPU());

while (true)
{
    await PrintCpuUsage();
}

static void ConsumeCPU()
{
    while (true) ;
}

static async Task PrintCpuUsage()
{
    var startTime = DateTime.UtcNow;
    var startCpuUsage = Process.GetCurrentProcess().TotalProcessorTime;

    await Task.Delay(1000);

    var endTime = DateTime.UtcNow;
    var endCpuUsage = Process.GetCurrentProcess().TotalProcessorTime;

    var cpuUsedMs = (int)(endCpuUsage - startCpuUsage).TotalMilliseconds;
    var totalMsPassed = (int)(endTime - startTime).TotalMilliseconds;
    Console.Clear();
    Console.WriteLine($"CPU:{cpuUsedMs}ms Watch:{totalMsPassed}ms");
}

Answer 1

Hello Martin,

I think that I am getting closer to understanding what is happening and that suggests to me that you will have to update your performance analysis techniques.

Using ETW under Windows 10, one often sees sequences of events like this:

The first clock interrupt entry is the hardware clock interrupt; the lower bit of the final value for that entry indicates that this processor (0) is the clock owner. The next two clock interrupt entries occur as a result of an interprocessor interrupt (IPI) - this can be verified by examining the stacks for the three clock interrupt events. The clock interrupt is forwarded, via IPI, to all processors that are not "idle".

This behaviour gives the results for CPU usage time that you have observed up to Windows 10.

Under Windows 11, I see this:

The differences are that a new bit (mask 0x10) is set on all clock interrupt events and clock interrupt events always occur just once per "tick" (i.e. no instances of clock interrupt events separated by tenths of microseconds on different processors).

This could just be an artefact of ETW tracing under Windows 11, but it ties in nicely with the observed behaviour of the thread/process CPU usage counters. More work is needed...

Gary

Answer 2

As I suspected this was a bug in Windows 11. I know this as it's been fixed in todays 23H2 Build 25936 and my test proves this as the two idle times are now much the same.

Answer 3

I know this as it's been fixed in todays 23H2 Build 25936

@red-ray

Nothing changed? Check the disassembly of those kernelbase functions, they're still using the exact same broken NtQuerySystemInformation behavior as previous versions of Windows.

The SIV64X tool in your screenshot however was updated and their changelog mentions a workaround... They're now bypassing kernelbase.dll (NtQuerySystemInformation) and are instead calling NtQuerySystemInformationEx directly which is why you're seeing correct values from SIV64X - everything else using GetSystemTimes/GetSystemInfo from kernelbase (NtQuerySystemInformation) still has issues with Windows 11.

Answer 4

Hello Martin,

As simple as your question might appear, it is fraught with imponderables. Here are some examples:

The time, as reported by DateTime.UtcNow, is derived from the clock tick interrupt; between clock interrupts, the time value does not change; two measurements made just microseconds apart might differ by tens of milliseconds if a clock interrupt occurs between the measurements.

The query of processor usage of threads and processes is obtained by reading values from kernel data structures. The processor usage is not "continuously" updated in this data structure while a thread is running; it might be updated on clock ticks, quantum ends, context switch out, etc. Without knowing implementation details, we can't be sure exactly what this value means for a running thread.

The statement "When an action takes 1 second to execute and only performs cpu operations, we except 1 second of cpu time" is näive. The CPU frequency can and does often change and fewer instructions are executed in some 1 second intervals compared to other 1 second intervals. I think that processor cycles are used to measure consumed CPU time and that the value is normalised via the "nominal" speed of the processor to give a time in (micro)seconds.

I stopped trying to think of other weaknesses in this type of test when I thought of three, so there might be more...

Gary

Answer 5

Hello Martin,

Thanks, the trace data is good. Below are some easy representations of the data.

The CPU usage of the "busy" thread is 14935.1855 milliseconds, measured with 0.1 microsecond accuracy of the time between switch-in and switch-out events. Some time was spent waiting, but probably during thread start-up and run-down.

When the thread stopped, it had accumulated 573 CPU units in kernel mode and 165 units in user mode. (573 + 165) * 15.625 = 11531.25 milliseconds. Its "CycleTime" was 0x89CE0FBDA = 36991728602 units. The "nominal" "CPUSpeed" is 2496 MHz; 36991728602 / 2496 = 14820 milliseconds.

The "busy" thread mostly runs on processors 0, 1, 2 and 3. 36991728602 / 11531 = 3208 MHz. This is plausibly a mix of the frequencies of processors 0 to 3.

More work is needed to investigate whether CPU frequency actually accounts for the numerical results and whether some system/CPU characteristics (such as whether RDTSC is a constant rate counter) are being incorrectly queried/read.

Gary