Runtime: SystemNative_GetCpuUtilization assert failure

[stephentoub]

https://mc.dot.net/#/user/dotnet-bot/pr~2Fdotnet~2Fcorefx~2Frefs~2Fpull~2F37996~2Fmerge/test~2Ffunctional~2Fcli~2Finnerloop~2F/20190528.42/workItem/System.Runtime.Extensions.Tests/wilogs

  Discovering: System.Runtime.Extensions.Tests (method display = ClassAndMethod, method display options = None)
  Discovered:  System.Runtime.Extensions.Tests (found 805 of 887 test cases)
  Starting:    System.Runtime.Extensions.Tests (parallel test collections = on, max threads = 4)
    System.Tests.EnvironmentTests.GetFolderPath_UapExistAndAccessible [SKIP]
      Condition(s) not met: "IsWindows10Version1709OrGreater", "IsInAppContainer"
    System.Tests.EnvironmentTests.GetFolderPath_UapNotEmpty [SKIP]
      Condition(s) not met: "IsWindows10Version1709OrGreater", "IsInAppContainer"
Assertion failed: (cpuUtilization >= 0 && cpuUtilization <= 100), function SystemNative_GetCpuUtilization, file /Users/vsts/agent/2.150.3/work/1/s/src/Native/Unix/System.Native/pal_time.c, line 200.
./RunTests.sh: line 175: 51998 Abort trap: 6           (core dumped) "$RUNTIME_PATH/dotnet" xunit.console.dll System.Runtime.Extensions.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=nonnetcoreapptests -notrait category=nonosxtests -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing $RSP_FILE

[ViktorHofer]

Happened again: https://mc.dot.net/#/user/dotnet-bot/pr~2Fdotnet~2Fcorefx~2Frefs~2Fpull~2F37900~2Fmerge/test~2Ffunctional~2Fcli~2Finnerloop~2F/20190529.43/workItem/System.Runtime.Extensions.Tests/wilogs

===========================================================================================================
~/dotnetbuild/work/7081b6ce-4205-4058-ac41-7b0a07a37dfb/Work/cbd881a4-295c-4458-98b7-42adeb3fcfe2/Exec ~/dotnetbuild/work/7081b6ce-4205-4058-ac41-7b0a07a37dfb/Work/cbd881a4-295c-4458-98b7-42adeb3fcfe2/Exec
  Discovering: System.Runtime.Extensions.Tests (method display = ClassAndMethod, method display options = None)
  Discovered:  System.Runtime.Extensions.Tests (found 805 of 887 test cases)
  Starting:    System.Runtime.Extensions.Tests (parallel test collections = on, max threads = 4)
    System.Tests.EnvironmentTests.GetFolderPath_UapExistAndAccessible [SKIP]
      Condition(s) not met: "IsWindows10Version1709OrGreater", "IsInAppContainer"
    System.Tests.EnvironmentTests.GetFolderPath_UapNotEmpty [SKIP]
      Condition(s) not met: "IsWindows10Version1709OrGreater", "IsInAppContainer"
Assertion failed: (cpuUtilization >= 0 && cpuUtilization <= 100), function SystemNative_GetCpuUtilization, file /Users/vsts/agent/2.150.3/work/1/s/src/Native/Unix/System.Native/pal_time.c, line 200.
./RunTests.sh: line 175: 46830 Abort trap: 6           (core dumped) "$RUNTIME_PATH/dotnet" xunit.console.dll System.Runtime.Extensions.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=nonnetcoreapptests -notrait category=nonosxtests -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing $RSP_FILE
~/dotnetbuild/work/7081b6ce-4205-4058-ac41-7b0a07a37dfb/Work/cbd881a4-295c-4458-98b7-42adeb3fcfe2/Exec
----- end 16:11:29 ----- exit code 134 ----------------------------------------------------------

[ViktorHofer]

Happens very frequently now: https://mc.dot.net/#/user/dotnet-bot/pr~2Fdotnet~2Fcorefx~2Frefs~2Fpull~2F37358~2Fmerge/test~2Ffunctional~2Fcli~2Finnerloop~2F/20190530.4/workItem/System.Runtime.Extensions.Tests/wilogs

[stephentoub]

@filipnavara, could you take a look?

[Anipik]

Its happening really frequently on the local machine as well. I am looking into it

[Anipik]

There are a couple of issues. The way we are using the interop here is not correct https://github.com/dotnet/corefx/blob/master/src/Common/src/CoreLib/System/AppDomain.Unix.cs#L14

The native function tells amount of cpu utilization by the process from the last recorded time(which could be previous call to this function or the process start time) to the current time.
here the input cpuinfo ref is zero. We need to correct this implementation.

kernalTime  310000000
UserTime  3600000000
resolution  1000000000
timestamp  762054685492600
currentTime  1241063584
lastRecordedCurrentTime  0
lastRecordedKernelTime  0
lastRecordedUserTime  0
cpuTotalTime  1241063584
cpuTotalTime with processors  2482127168
cpuTotalTime  2482127168
cpuBusyTime  3910000000
ccpuUtilization  157
dotnet: /git/corefx/src/Native/Unix/System.Native/pal_time.c:215: int32_t SystemNative_GetCpuUtilization(ProcessCpuInformation *): Assertion `cpuUtilization >= 0 && cpuUtilization <= 100' failed.
Aborted

The other problem is an overflow problem https://github.com/dotnet/corefx/blob/master/src/Native/Unix/System.Native/pal_time.c#L172
the multiplication operation is leading to an overflow here.

We are using this code for polling in runtime. so we only care about difference there.
The overflow code could be a recent bug as well.

@tannergooding can you take a look if you missed any scenario in your recent changes to this api ?

[tannergooding]

That particular line of code hasn't been touched since the code was introduced ~4 months ago.

If overflow is a concern here, you will need to either use uint128 (expensive) or double (potentially lossy).

System.Diagnostics.Stopwatch does the latter for the same scenario.

[stephentoub]

The native function tells amount of cpu utilization by the process from the last recorded time(which could be previous call to this function or the process start time) to the current time.
here the input cpuinfo ref is zero. We need to correct this implementation.

I'm not following. What are you suggesting it should be? If it's wrong, isn't the other use of it at https://github.com/dotnet/coreclr/blob/9773db1e7b1acb3ec75c9cc0e36bd62dcbacd6d5/src/System.Private.CoreLib/src/System/Diagnostics/Eventing/RuntimeEventSourceHelper.Unix.cs#L15 also wrong, since the first time it's used, it'll similarly be default initialized?

[Anipik]

I think the polling counters are using the first value just as an offset\bogus value. They don't care about the cpu utilization at the first point.
They use it calculate cpu utilization between 2 points.

[Anipik]

https://github.com/dotnet/corefx/blob/master/src/Native/Unix/System.Native/pal_time.c#L170
returns the current timestamp where as https://github.com/dotnet/corefx/blob/master/src/Native/Unix/System.Native/pal_time.c#L154
returns time durations for the current process.
so we need to subtract some offset from the first to make both of these comparable

[stephentoub]

I think the polling counters are using the first value just as an offset\bogus value

Sure, but https://github.com/dotnet/corefx/blob/master/src/Common/src/CoreLib/System/AppDomain.Unix.cs#L14 always ignores the utilization; it's calling it just to get at the lastRecordedUserTime. And because it's using a new default value each time, isn't it effectively always like the "first" call?

[Anipik]

yes for MonitoringTotalProcessorTime its always like first call.

sorry I missed that we are only using lastRecordedUserTime. But would it make sense to just right an interop for this function https://github.com/dotnet/corefx/blob/master/src/Native/Unix/System.Native/pal_time.c#L154

Btw the assert error is due to the overflow that I mentioned https://github.com/dotnet/corefx/issues/38001#issuecomment-497492876

The coreclr people should also be hitting it because I am able to repro it like 4 out of 10 times.

[stephentoub]

would it make sense to just right an interop for this function

I considered it, but this method is really just a compat implementation and performance here is not critical, and as such I preferred to just use the existing function that does a bit of unnecessary work rather than carry around additional code that also needs to be maintained.

Btw the assert error is due to the overflow that I mentioned

Great, that makes more sense. Thanks for tracking it down :)

[Anipik]

Okay then I will just fix the overflow error

[danmosemsft]

Good sleuthing @anipik

[Anipik]

Thanks :)