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

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 3

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 4

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

Answer 5

Maybe you can test with Native APIs.

I tested with your loop on Windows 10 22H2, but I don't know if structures like SYSTEM_BASIC_INFORMATION have changed on Windows 11 (maybe some fields must be added...) :

            //bool bRet = SetPriorityClass(System.Diagnostics.Process.GetCurrentProcess().Handle, REALTIME_PRIORITY_CLASS);
            bool bRet = SetPriorityClass(GetCurrentProcess(), REALTIME_PRIORITY_CLASS);
            bRet = SetThreadPriority(GetCurrentThread(), THREAD_PRIORITY_HIGHEST);

            List<SYSTEM_PROCESSOR_PERFORMANCE_INFORMATION> sppiBegin, sppiEnd;
            int nProcessors = 0;
            sppiBegin = GetSPPI(out nProcessors);
            if (sppiBegin.Count > 0)
            {
                var builder = new StringBuilder();
                for (int i = 0; i < 100000; i++)
                {
                    builder.Append(i);
                    builder.ToString();
                }
                //System.Threading.Thread.Sleep(5000);
                sppiEnd = GetSPPI(out nProcessors);

                TIME_FIELDS tf;
                LARGE_INTEGER liIdle, liUser, liKernel, liElapsed, liDPC, liInterrupt, liTotalIdle, liTotalUser, liTotalKernel, liTotalElapsed;
                liKernel = new LARGE_INTEGER();
                liUser = new LARGE_INTEGER();
                liIdle = new LARGE_INTEGER();
                liDPC = new LARGE_INTEGER();
                liInterrupt = new LARGE_INTEGER();
                liElapsed = new LARGE_INTEGER();
                liTotalIdle.QuadPart = 0;
                liTotalUser.QuadPart = 0;
                liTotalKernel.QuadPart = 0;
                liTotalElapsed.QuadPart = 0;
                for (int i = 0; i < nProcessors; i++)
                {
                    liIdle.QuadPart = sppiEnd[i].IdleTime.QuadPart - sppiBegin[i].IdleTime.QuadPart;
                    liUser.QuadPart = sppiEnd[i].UserTime.QuadPart - sppiBegin[i].UserTime.QuadPart;
                    liKernel.QuadPart = sppiEnd[i].KernelTime.QuadPart - sppiBegin[i].KernelTime.QuadPart;
                    liElapsed.QuadPart = liKernel.QuadPart + liUser.QuadPart;
                    liKernel.QuadPart -= liIdle.QuadPart;
                    liDPC.QuadPart = sppiEnd[i].DpcTime.QuadPart - sppiBegin[i].DpcTime.QuadPart;
                    liInterrupt.QuadPart = sppiEnd[i].InterruptTime.QuadPart - sppiBegin[i].InterruptTime.QuadPart;

                    liTotalIdle.QuadPart += liIdle.QuadPart;
                    liTotalUser.QuadPart += liUser.QuadPart;
                    liTotalKernel.QuadPart += liKernel.QuadPart;
                    liTotalElapsed.QuadPart += liElapsed.QuadPart;

                    Console.WriteLine("Processor : {0}", i.ToString());
                    RtlTimeToTimeFields(ref liKernel, out tf);
                    Console.WriteLine("\tKernel : {0:D2}:{1:D2}:{2:D2}.{3:D3}", tf.Hour, tf.Minute, tf.Second, tf.Milliseconds);
                    RtlTimeToTimeFields(ref liUser, out tf);
                    Console.WriteLine("\tUser : {0:D2}:{1:D2}:{2:D2}.{3:D3}", tf.Hour, tf.Minute, tf.Second, tf.Milliseconds);
                    RtlTimeToTimeFields(ref liIdle, out tf);
                    Console.WriteLine("\tIdle : {0:D2}:{1:D2}:{2:D2}.{3:D3}", tf.Hour, tf.Minute, tf.Second, tf.Milliseconds);
                    RtlTimeToTimeFields(ref liDPC, out tf);
                    Console.WriteLine("\tDPC : {0:D2}:{1:D2}:{2:D2}.{3:D3}", tf.Hour, tf.Minute, tf.Second, tf.Milliseconds);
                    RtlTimeToTimeFields(ref liInterrupt, out tf);
                    Console.WriteLine("\tInterrupt : {0:D2}:{1:D2}:{2:D2}.{3:D3}", tf.Hour, tf.Minute, tf.Second, tf.Milliseconds);

                    RtlTimeToTimeFields(ref liElapsed, out tf);
                    Console.WriteLine("\tElapsed: {0:D2}:{1:D2}:{2:D2}.{3:D3}", tf.Hour, tf.Minute, tf.Second, tf.Milliseconds);
                }
            }

Utility function :

        private List<SYSTEM_PROCESSOR_PERFORMANCE_INFORMATION> GetSPPI(out int nProcessors)
        {
            List<SYSTEM_PROCESSOR_PERFORMANCE_INFORMATION> ListSPPI = new List<SYSTEM_PROCESSOR_PERFORMANCE_INFORMATION>();
            nProcessors = 0;

            SYSTEM_BASIC_INFORMATION sbi = new SYSTEM_BASIC_INFORMATION();
            IntPtr pBuffer = Marshal.AllocHGlobal(Marshal.SizeOf(typeof(SYSTEM_BASIC_INFORMATION)));
            int nLength = Marshal.SizeOf(typeof(SYSTEM_BASIC_INFORMATION));
            int nReturnLength = 0;
            try
            {
                // nStatus = 0xc0000004 STATUS_INFO_LENGTH_MISMATCH
                int nStatus = NtQuerySystemInformation(SYSTEM_INFORMATION_CLASS.SystemBasicInformation, pBuffer, nLength, ref nReturnLength);
                if (nStatus == STATUS_SUCCESS)
                {
                    sbi = (SYSTEM_BASIC_INFORMATION)Marshal.PtrToStructure(pBuffer, typeof(SYSTEM_BASIC_INFORMATION));
                    nProcessors = sbi.NumberOfProcessors;
                    Marshal.FreeHGlobal(pBuffer);
                    int nLengthSPPI = sbi.NumberOfProcessors * Marshal.SizeOf(typeof(SYSTEM_PROCESSOR_PERFORMANCE_INFORMATION));
                    IntPtr pBufferSPPI = Marshal.AllocHGlobal(nLengthSPPI);
                    nStatus = NtQuerySystemInformation(SYSTEM_INFORMATION_CLASS.SystemProcessorPerformanceInformation, pBufferSPPI, nLengthSPPI, ref nReturnLength);
                    if (nStatus == STATUS_SUCCESS)
                    {
                        IntPtr pBufferNew = pBufferSPPI;
                        for (int nIndex = 0; nIndex < sbi.NumberOfProcessors; nIndex++)
                        {
                            SYSTEM_PROCESSOR_PERFORMANCE_INFORMATION sppi = (SYSTEM_PROCESSOR_PERFORMANCE_INFORMATION)Marshal.PtrToStructure(pBufferNew, typeof(SYSTEM_PROCESSOR_PERFORMANCE_INFORMATION));
                            ListSPPI.Add(sppi);
                            pBufferNew += Marshal.SizeOf(typeof(SYSTEM_PROCESSOR_PERFORMANCE_INFORMATION));
                        }
                        Marshal.FreeHGlobal(pBufferSPPI);
                    }
                }
                else
                {
                    throw new Win32Exception(RtlNtStatusToDosError(nStatus));
                }
            }
            catch (Win32Exception wex)
            {
                System.Windows.Forms.MessageBox.Show(("Error : " + wex.Message), "Error", MessageBoxButtons.OK, MessageBoxIcon.Error);
            }
          
            return ListSPPI;
        }
    }

Declarations :

        public const int STATUS_SUCCESS = 0x0;
        public const int STATUS_INFO_LENGTH_MISMATCH = unchecked((int)0xC0000004);

        [DllImport("NtDll.dll", SetLastError = true, CharSet = CharSet.Unicode)]
        public static extern int NtQuerySystemInformation(SYSTEM_INFORMATION_CLASS SystemInformationClass, IntPtr SystemInformation, int SystemInformationLength, ref int ReturnLength);

        public enum SYSTEM_INFORMATION_CLASS
        {
            SystemBasicInformation,
            SystemProcessorInformation,
            SystemPerformanceInformation,
            SystemTimeOfDayInformation,
            SystemPathInformation,
            SystemProcessInformation,
            SystemCallCountInformation,
            SystemDeviceInformation,
            SystemProcessorPerformanceInformation,
            SystemFlagsInformation,
            SystemCallTimeInformation,
            SystemModuleInformation,
            SystemLocksInformation,
            SystemStackTraceInformation,
            SystemPagedPoolInformation,
            SystemNonPagedPoolInformation,
            SystemHandleInformation,
            SystemObjectInformation,
            SystemPageFileInformation,
            SystemVdmInstemulInformation,
            SystemVdmBopInformation,
            SystemFileCacheInformation,
            SystemPoolTagInformation,
            SystemInterruptInformation,
            SystemDpcBehaviorInformation,
            SystemFullMemoryInformation,
            SystemLoadGdiDriverInformation,
            SystemUnloadGdiDriverInformation,
            SystemTimeAdjustmentInformation,
            SystemSummaryMemoryInformation,
            SystemMirrorMemoryInformation,
            SystemPerformanceTraceInformation,
            SystemObsolete0,
            SystemExceptionInformation,
            SystemCrashDumpStateInformation,
            SystemKernelDebuggerInformation,
            SystemContextSwitchInformation,
            SystemRegistryQuotaInformation,
            SystemExtendServiceTableInformation,
            SystemPrioritySeperation,
            SystemVerifierAddDriverInformation,
            SystemVerifierRemoveDriverInformation,
            SystemProcessorIdleInformation,
            SystemLegacyDriverInformation,
            SystemCurrentTimeZoneInformation,
            SystemLookasideInformation,
            SystemTimeSlipNotification,
            SystemSessionCreate,
            SystemSessionDetach,
            SystemSessionInformation,
            SystemRangeStartInformation,
            SystemVerifierInformation,
            SystemVerifierThunkExtend,
            SystemSessionProcessInformation,
            SystemLoadGdiDriverInSystemSpace,
            SystemNumaProcessorMap,
            SystemPrefetcherInformation,
            SystemExtendedProcessInformation,
            SystemRecommendedSharedDataAlignment,
            SystemComPlusPackage,
            SystemNumaAvailableMemory,
            SystemProcessorPowerInformation,
            SystemEmulationBasicInformation,
            SystemEmulationProcessorInformation,
            SystemExtendedHandleInformation,
            SystemLostDelayedWriteInformation,
            SystemBigPoolInformation,
            SystemSessionPoolTagInformation,
            SystemSessionMappedViewInformation,
            SystemHotpatchInformation,
            SystemObjectSecurityMode,
            SystemWatchdogTimerHandler,
            SystemWatchdogTimerInformation,
            SystemLogicalProcessorInformation,
            SystemWow64SharedInformationObsolete,
            SystemRegisterFirmwareTableInformationHandler,
            SystemFirmwareTableInformation,
            SystemModuleInformationEx,
            SystemVerifierTriageInformation,
            SystemSuperfetchInformation,
            SystemMemoryListInformation,
            SystemFileCacheInformationEx,
            SystemThreadPriorityClientIdInformation,
            SystemProcessorIdleCycleTimeInformation,
            SystemVerifierCancellationInformation,
            SystemProcessorPowerInformationEx,
            SystemRefTraceInformation,
            SystemSpecialPoolInformation,
            SystemProcessIdInformation,
            SystemErrorPortInformation,
            SystemBootEnvironmentInformation,
            SystemHypervisorInformation,
            SystemVerifierInformationEx,
            SystemTimeZoneInformation,
            SystemImageFileExecutionOptionsInformation,
            SystemCoverageInformation,
            SystemPrefetchPatchInformation,
            SystemVerifierFaultsInformation,
            SystemSystemPartitionInformation,
            SystemSystemDiskInformation,
            SystemProcessorPerformanceDistribution,
            SystemNumaProximityNodeInformation,
            SystemDynamicTimeZoneInformation,
            SystemCodeIntegrityInformation,
            SystemProcessorMicrocodeUpdateInformation,
            SystemProcessorBrandString,
            SystemVirtualAddressInformation,
            SystemLogicalProcessorAndGroupInformation,
            SystemProcessorCycleTimeInformation,
            SystemStoreInformation,
            SystemRegistryAppendString,
            SystemAitSamplingValue,
            SystemVhdBootInformation,
            SystemCpuQuotaInformation,
            SystemNativeBasicInformation,
            SystemErrorPortTimeouts,
            SystemLowPriorityIoInformation,
            SystemBootEntropyInformation,
            SystemVerifierCountersInformation,
            SystemPagedPoolInformationEx,
            SystemSystemPtesInformationEx,
            SystemNodeDistanceInformation,
            SystemAcpiAuditInformation,
            SystemBasicPerformanceInformation,
            SystemQueryPerformanceCounterInformation,
            SystemSessionBigPoolInformation,
            SystemBootGraphicsInformation,
            SystemScrubPhysicalMemoryInformation,
            SystemBadPageInformation,
            SystemProcessorProfileControlArea,
            SystemCombinePhysicalMemoryInformation,
            SystemEntropyInterruptTimingInformation,
            SystemConsoleInformation,
            SystemPlatformBinaryInformation,
            SystemThrottleNotificationInformation,
            SystemHypervisorProcessorCountInformation,
            SystemDeviceDataInformation,
            SystemDeviceDataEnumerationInformation,
            SystemMemoryTopologyInformation,
            SystemMemoryChannelInformation,
            SystemBootLogoInformation,
            SystemProcessorPerformanceInformationEx,
            SystemSpare0,
            SystemSecureBootPolicyInformation,
            SystemPageFileInformationEx,
            SystemSecureBootInformation,
            SystemEntropyInterruptTimingRawInformation,
            SystemPortableWorkspaceEfiLauncherInformation,
            SystemFullProcessInformation,
            MaxSystemInfoClass // = 0x0095
        }

        [StructLayout(LayoutKind.Sequential)]
        public struct SYSTEM_BASIC_INFORMATION
        {
            public uint Reserved;
            public uint TimerResolution;
            public uint PageSize;
            public uint NumberOfPhysicalPages;
            public uint LowestPhysicalPageNumber;
            public uint HighestPhysicalPageNumber;
            public uint AllocationGranularity;
            public UIntPtr MinimumUserModeAddress;
            public UIntPtr MaximumUserModeAddress;
            public UIntPtr ActiveProcessorsAffinityMask;
            public byte NumberOfProcessors;
        }      

        [StructLayout(LayoutKind.Sequential, CharSet = CharSet.Unicode)]
        public struct SYSTEM_PROCESSOR_PERFORMANCE_INFORMATION
        {
            public LARGE_INTEGER IdleTime;
            public LARGE_INTEGER KernelTime;
            public LARGE_INTEGER UserTime;
            //[MarshalAs(UnmanagedType.ByValArray, SizeConst = 2)]
            //public LARGE_INTEGER[] Reserved1;
            //public uint Reserved2;
            public LARGE_INTEGER DpcTime;
            public LARGE_INTEGER InterruptTime;
            public uint InterruptCount;
        }

        [StructLayout(LayoutKind.Explicit)]
        public struct LARGE_INTEGER
        {
            [FieldOffset(0)]
            public int LowPart;
            [FieldOffset(4)]
            public int HighPart;
            [FieldOffset(0)]
            public long QuadPart;
        }

        [DllImport("NtDll.dll", SetLastError = true, CharSet = CharSet.Unicode)]
        public static extern void RtlTimeToTimeFields(ref LARGE_INTEGER Time, out TIME_FIELDS TimeFields);

        [StructLayout(LayoutKind.Sequential, CharSet = CharSet.Unicode)]
        public struct TIME_FIELDS
        {
            public short Year;
            public short Month;
            public short Day;
            public short Hour;
            public short Minute;
            public short Second;
            public short Milliseconds;
            public short Weekday;
        }

        [DllImport("Kernel32.dll", SetLastError = true, CharSet = CharSet.Unicode)]
        public static extern bool SetPriorityClass(IntPtr hProcess, uint dwPriorityClass);

        [DllImport("Kernel32.dll", SetLastError = true, CharSet = CharSet.Unicode)]
        public static extern bool SetThreadPriority(IntPtr hThread, int nPriority);

        public const int NORMAL_PRIORITY_CLASS = 0x00000020;
        public const int IDLE_PRIORITY_CLASS = 0x00000040;
        public const int HIGH_PRIORITY_CLASS = 0x00000080;
        public const int REALTIME_PRIORITY_CLASS = 0x00000100;
        public const int BELOW_NORMAL_PRIORITY_CLASS = 0x00004000;
        public const int ABOVE_NORMAL_PRIORITY_CLASS = 0x00008000;

        public const int THREAD_BASE_PRIORITY_LOWRT = 15;  // value that gets a thread to LowRealtime-1
        public const int THREAD_BASE_PRIORITY_MAX = 2;   // maximum thread base priority boost
        public const int THREAD_BASE_PRIORITY_MIN = (-2);  // minimum thread base priority boost
        public const int THREAD_BASE_PRIORITY_IDLE = (-15); // value that gets a thread to idle
        public const int THREAD_PRIORITY_LOWEST = THREAD_BASE_PRIORITY_MIN;
        public const int THREAD_PRIORITY_BELOW_NORMAL = (THREAD_PRIORITY_LOWEST + 1);
        public const int THREAD_PRIORITY_NORMAL = 0;
        public const int THREAD_PRIORITY_HIGHEST = THREAD_BASE_PRIORITY_MAX;
        public const int THREAD_PRIORITY_ABOVE_NORMAL = (THREAD_PRIORITY_HIGHEST - 1);
        public const int MAXLONG = 0x7fffffff;  
        public const int THREAD_PRIORITY_ERROR_RETURN = (MAXLONG);

        public const int THREAD_PRIORITY_TIME_CRITICAL = THREAD_BASE_PRIORITY_LOWRT;
        public const int THREAD_PRIORITY_IDLE = THREAD_BASE_PRIORITY_IDLE;

        [DllImport("Kernel32.dll", SetLastError = true, CharSet = CharSet.Unicode)]
        public static extern IntPtr GetCurrentThread();

        [DllImport("Kernel32.dll", SetLastError = true, CharSet = CharSet.Unicode)]
        public static extern IntPtr GetCurrentProcess();

        [DllImport("Kernel32.dll", SetLastError = true, CharSet = CharSet.Unicode)]
        private static extern uint FormatMessage(int dwFlags, IntPtr lpSource, int dwMessageId, int dwLanguageId, ref IntPtr lpBuffer, int nSize, IntPtr Arguments);

        public const int FORMAT_MESSAGE_ALLOCATE_BUFFER = 0x00000100;
        public const int FORMAT_MESSAGE_IGNORE_INSERTS = 0x00000200;
        public const int FORMAT_MESSAGE_FROM_SYSTEM = 0x00001000;

        [DllImport("NtDll.dll", SetLastError = true, CharSet = CharSet.Unicode)]
        public static extern int RtlNtStatusToDosError(int Status);