Test failure System.Diagnostics.Tests.ProcessTests.TotalProcessorTime_PerformLoop_TotalProcessorTimeValid

[v-wenyuxu]

Failed in: runtime-coreclr libraries-jitstress 20230524.1

Failed tests:

net8.0-linux-Release-arm64-CoreCLR_checked-jitstress1_tiered-(Ubuntu.1804.Arm64.Open)[email protected]/dotnet-buildtools/prereqs:ubuntu-18.04-helix-arm64v8

- System.Diagnostics.Tests.ProcessTests.TotalProcessorTime_PerformLoop_TotalProcessorTimeValid

Error message:

Assert.InRange() Failure
Range:  (0 - 1)
Actual: 1.0463972542536049

Stack trace:

   at System.Diagnostics.Tests.ProcessTests.TotalProcessorTime_PerformLoop_TotalProcessorTimeValid() in /_/src/libraries/System.Diagnostics.Process/tests/ProcessTests.cs:line 910
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodInvoker.cs:line 59

[ghost]

Tagging subscribers to this area: @dotnet/area-system-diagnostics-process
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Failed in: runtime-coreclr libraries-jitstress 20230524.1

Failed tests:

net8.0-linux-Release-arm64-CoreCLR_checked-jitstress1_tiered-(Ubuntu.1804.Arm64.Open)[email protected]/dotnet-buildtools/prereqs:ubuntu-18.04-helix-arm64v8

- System.Diagnostics.Tests.ProcessTests.TotalProcessorTime_PerformLoop_TotalProcessorTimeValid

Error message:

Assert.InRange() Failure
Range:  (0 - 1)
Actual: 1.0463972542536049

Stack trace:

   at System.Diagnostics.Tests.ProcessTests.TotalProcessorTime_PerformLoop_TotalProcessorTimeValid() in /_/src/libraries/System.Diagnostics.Process/tests/ProcessTests.cs:line 910
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodInvoker.cs:line 59

Author:	v-wenyuxu
Assignees:	-
Labels:	arch-arm64, area-System.Diagnostics.Process, os-linux, JitStress
Milestone:	-

[adamsitnik]

The person who is willing to work on this should verify in what scenario the asserted value could be more than 1 and either fix the test or find underlying bug.

runtime/src/libraries/System.Diagnostics.Process/tests/ProcessTests.cs

Lines 902 to 910 in 7cf329b

	TimeSpan processorTimeAfterSpin = Process.GetCurrentProcess().TotalProcessorTime;
	DateTime endTime = DateTime.UtcNow;
	double timeDiff = (endTime - startTime).TotalMilliseconds;
	double cpuTimeDiff = (processorTimeAfterSpin - processorTimeBeforeSpin).TotalMilliseconds;
	double cpuUsage = cpuTimeDiff / (timeDiff * Environment.ProcessorCount);
	Assert.InRange(cpuUsage, 0, 1);

[jakobbotsch]

The loop in that function may also go through OSR making it significantly slower (and consuming a lot more CPU), and given the high average load on test machines it does not surprise me that the test is flakey. There's a few more failures recently: https://runfo.azurewebsites.net/search/tests/?q=started%3A%7E7+name%3ATotalProcessorTimeValid

Maybe the test should just be deleted, or it should retry a few times before failing if the result is above the expected range.

[jakobbotsch]

The comment on the loop talks about 1 second of CPU time, yet the assert seems to try to validate that we expended less than 1 millisecond of CPU time. So maybe that's just what should be fixed? With OSR it's quite expected that this may take more than 1 ms since once it hits the threshold it will involve a full rejitting of the method.

[adamsitnik]

We could also just assert that the time is more than 0?

[danmoseley]

I cannot see how this can happen, unless it's some glitchy data in the /proc/./stat file. I will add logging.

[jakobbotsch]

@danmoseley what makes you say this has to be glitchy data? The failures show that the CPU time is just barely more than 1 millisecond – not that much given that a full rejitting may have occurred.

[danmoseley]

Am I misreading..cpu time is the numerator here, and the result is unexpectedly high. It means cpu time was high?

[danmoseley]

If you merge my PR we will discover..

[jakobbotsch]

Am I misreading..cpu time is the numerator here, and the result is unexpectedly high. It means cpu time was high?

No, I was misreading it...

[danmoseley]

waiting for new hit on https://runfo.azurewebsites.net/search/tests/?q=started%3A%7E7+name%3ATotalProcessorTimeValid

[danmoseley]

Rather disappointed that it hasn't happened again yet.

[danmoseley]

Nothing
https://runfo.azurewebsites.net/search/tests/?q=started%3A%7E14+name%3ATotalProcessorTimeValid+result%3Afailed+targetBranch%3Amain

I will close and if it happens again we will know more.

[jakobbotsch]

We hit this in superpmi-collect: https://helixri107v0xdcypoyl9e7f.blob.core.windows.net/dotnet-runtime-refs-heads-main-e4ba4e2b24654b5292/System.Diagnostics.Process.Tests/1/console.f3cae831.log?sv=2021-08-06&se=2024-01-27T17%3A55%3A37Z&sr=c&sp=rl&sig=cEizO0GVk3rmTXFRQ0nozUzyNav4Ro9rpqRZSgQNYik%3D

    System.Diagnostics.Tests.ProcessTests.TotalProcessorTime_PerformLoop_TotalProcessorTimeValid [FAIL]
      Assertion failed. 1.1390753259881705 is not in range [0,1]. proc time before:51296.875 proc time after:51484.375 timeDiff:82.3036 cpuTimeDiff:187.5 Environment.ProcessorCount:2
      Stack Trace:
        /_/src/libraries/System.Diagnostics.Process/tests/ProcessTests.cs(922,0): at System.Diagnostics.Tests.ProcessTests.TotalProcessorTime_PerformLoop_TotalProcessorTimeValid()
           at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
        /_/src/coreclr/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.CoreCLR.cs(36,0): at System.Reflection.MethodBaseInvoker.InterpretedInvoke_Method(Object obj, IntPtr* args)
        /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.cs(57,0): at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr)

Is it possible that using DateTime.UtcNow here is the problem? IIRC, it might have bad resolution (up to 16 ms) in some cases? If we add 16ms to the timeDiff then the ratio becomes 0.95. Maybe we should switch to Stopwatch?

[danmoseley]

@jakobbotsch Could be - whatever the cause it is probably reasonable to just make the wait longer. Do you want to make that change?