Process.GetCurrentProcess().TotalProcessorTime returns strange values on macOS

[gregkalapos]

I'd like to gather CPU usage information and for this I use the System.Diagnostics.Process class. On macOS the Process.TotalProcessorTime property seems to return values that are higher than I'd expect. E.g. in a 5 sec timeframe with a 12 core CPU I see values higher than 12 * 5sec.

Reproducer (This returns valid values both on Windows - compared to Task Manager - and Linux, but returns seemingly invalid values on macOS):

using System;
using System.Timers;

namespace ProcessTimeRepro
{
    class Program
    {
        static void Main(string[] args)
        {
            var t = new Timer(5000);

            var process = System.Diagnostics.Process.GetCurrentProcess();

            Console.WriteLine($"Pid: {process.Id}");
            Console.WriteLine($"ProcessorCount: {Environment.ProcessorCount}");

            var b = false;
            var lastSample = DateTime.UtcNow;
            var lastTotalProcessorTime = new TimeSpan();
            
            t.Elapsed += (sender, eventArgs) =>
            {
                var currentDateTime = DateTime.UtcNow;
                var currentTotalProcessorTime = process.TotalProcessorTime;
                if (b)
                {
                    var timeDiff = (currentDateTime - lastSample).TotalMilliseconds;
                    var cpuUsage = (currentTotalProcessorTime - lastTotalProcessorTime).TotalMilliseconds;
                    
                    Console.WriteLine("=======timer elapsed=======");
                    Console.WriteLine($"total: {currentTotalProcessorTime}");
                    Console.WriteLine($"system: {process.UserProcessorTime}");
                    Console.WriteLine($"user: {process.PrivilegedProcessorTime}");
                    Console.WriteLine();
                    Console.WriteLine($"timeDiff: {timeDiff} ms");
                    Console.WriteLine($"cpuUsageDiff: {cpuUsage} ms");
                    Console.WriteLine($"Cpu usage: {cpuUsage / (timeDiff * Environment.ProcessorCount) * 100}%");
                    Console.WriteLine("=======timer elapsed end=======");
                    Console.WriteLine();
                }

                lastTotalProcessorTime = currentTotalProcessorTime;
                lastSample = currentDateTime;
                b = true;


            };

            t.Start();

            Console.WriteLine("Work starts");
            var rnd = new Random();
            for (int i = 0; i < int.MaxValue; i++)
            {
                if (rnd.Next() < 0) //make sure real work is done, this is not optimized away
                {
                    Console.WriteLine("bla");
                }
            }

            Console.WriteLine("Work done");

            Console.ReadLine();
        }
    }
}

In short: we have 1 thread doing some work (generate random numbers) for a while and a timer that captures CPU usage.

Output on macOS (macOS Mojave 10.14.4, MacBook Pro 2018, 2.9 Ghz Intel Core i9):

dotnet run -c Release
Pid: 2989
ProcessorCount: 12
Work starts
=======timer elapsed=======
total: 00:16:45.0497401
system: 00:16:34.7100833
user: 00:00:10.3697294

timeDiff: 4992.206 ms
cpuUsageDiff: 497341.0443 ms
Cpu usage: 830.195849790654%
=======timer elapsed end=======

=======timer elapsed=======
total: 00:25:04.1338311
system: 00:24:49.7922366
user: 00:00:14.3803124

timeDiff: 5004.88 ms
cpuUsageDiff: 499084.091 ms
Cpu usage: 830.995766465263%
=======timer elapsed end=======

Work done
=======timer elapsed=======
total: 00:26:53.6510655
system: 00:26:38.4277113
user: 00:00:15.2315355

timeDiff: 4997.881 ms
cpuUsageDiff: 109517.2344 ms
Cpu usage: 182.606112470465%
=======timer elapsed end=======

=======timer elapsed=======
total: 00:26:53.7347993
system: 00:26:38.4790252
user: 00:00:15.2648931

timeDiff: 4996.953 ms
cpuUsageDiff: 83.7338 ms
Cpu usage: 0.139641430821276%
=======timer elapsed end=======

E.g. when the timer fires the 2. time we have this output:

timeDiff: 5004.88 ms
cpuUsageDiff: 499084.091 ms

This means in a 5004.88ms time-slot this app consumed 499084.091 ms CPU, which is I think impossible. As you can see this is a 12 core machine, so in case all 12 cores do 100% work on this process the CPU time would be 12*5004.88ms, if I'm not mistaken, there is no way to have a higher CPU time in this time range. Also in the reproducer, the work is done on a single thread, so I'd expect to have a 100% CPU usage on 1 core and some minimal other work done by the timer (probably negligible), so for a timeDiff: 5004.88 ms the cpuUsageDiff should be also close to 5sec - and this is exactly what I see on Linux and Windows.

So either I do something wrong, or the value returned from Process.TotalProcessorTime is very inaccurate.

Also when I compare the increasing total value (that's the plain value of Process.TotalProcessorTime to Activity Monitor (for Windows people: that's the Task manager of macOS) or top I see very different numbers. top and Activity monitor report significantly lower numbers.

Are we sure that rusage_info_v3 returns info.ri_system_time and info.ri_user_time reported in 100-nanosecond units here?

[gregkalapos]

Update: Yeah, if I divide Process.TotalProcessorTime by 100 I get exactly the value that Activity monitor shows as CPU Time.

Tested with .NET Core 2.0 and 3.0.100-preview5-011568.

[danmoseley]

Thanks. Would you be willing to offer a PR? With some basic test (that checks that the value is the correct order of magnitude)

[gregkalapos]

Sure! I'd be very happy to help out with this.

I'm not 100% sure about the solution yet though. I suspect that there was a change in some macOS version. There was a problem in Go, which seems to be somewhat related: golang/go#22037, and this is also very suspicious: https://github.com/dotnet/corefx/issues/30391. So simply dividing by 100 here is probably not the way to go.

This is all what Apple says about this kernel function: https://developer.apple.com/documentation/kernel/rusage_info_v3?language=objc - basically undocumented, no unit is mentioned for the values.

So, this is all I know currently. I'll continue researching this - also happy to take advice in case someone knows more.

[stephentoub]

Thanks, @gregkalapos. You're right: it looks like the ri_user_time unit is nanoseconds, but TimeSpan's Int64-based constructor expects a value with a 100-nanosecond unit.

[stephentoub]

The fix should be in Process.OSX.cs, to divide ri_system_time and ri_user_time by 100 in the various time-related properties in which they're used, e.g.

private const int NanoSecondsTo100NanoSecondsFactor = 100;
...
public TimeSpan UserProcessorTime
{
    get
    {
        EnsureState(State.HaveNonExitedId);
        Interop.libproc.rusage_info_v3 info = Interop.libproc.proc_pid_rusage(_processId);
        return new TimeSpan(Convert.ToInt64(info.ri_user_time) / NanoSecondsTo100NanoSecondsFactor);
    }
}

This affects UserProcessorTime, PrivilegedProcessorTime, and TotalProcessorTime.

[gregkalapos]

@stephentoub Thanks! I'm happy to take this and implement.

I'll also try to come up with a test... probably it'd make sense to do something similar to my reproducer and assert that the CPU usage is not higher than timeframe/numberOfCores with some threshold.

One small question: are we totally sure this is true in every macOS version? Asking because of the linked issues in my previous comment.

[stephentoub]

I don't believe either of those issues are related.

[gregkalapos]

Ok, I'll then just do the /100 fix. Thank you.

[gregkalapos]

@danmosemsft one last question to this: I plan to support pre-3.0 versions with my library that reports CPU usage. My plan is to manually fix up these values in my code on macOS in versions earlier than 3.0.0-preview5 (including 2.1, 2.2).

There won't be any backport of this, right?

So, I'd just do something like:

if(version <= 3.0.0-preview5)
{
  //fix reported values on macOS
}

Is this a fair assumption?

[danmoseley]

@gregkalapos that's correct, this would not get backported. We have certain requirements in terms of impact, severity, and lack of workaround - this wouldn't meet that criteria. So I think your plan is good.

Just curious, what sort of library are you writing? Will it be public?

[gregkalapos]

@danmosemsft yes, it's completely open source, you can check it out: https://github.com/elastic/apm-agent-dotnet

It's part of the observability solution of Elastic. It's the APM Agent that sends prod. monitoring data.

[danmoseley]

Interesting! Beyond this issue, how have you found the experience of using .NET Core? Also, how difficult have you found it to support both .NET Core and .NET Framework? Finally, do you have any means to compare the performance?