[runtime-coreclr pgo] nativeruntimeeventsource test fails arm32 and x86

[EgorBo]

This test seems to be failing on all outerloop runtime-coreclr pgo pipelines

Unhandled exception. System.Exception: Condition 'Saw the ThreadPoolIOPack event' is not true
at Tracing.Tests.Common.Assert.True(String name, Boolean condition)
at Tracing.Tests.NativeRuntimeEventSourceTest.Main(String[] args)

Fails in various PRs, e.g.:
https://dev.azure.com/dnceng/public/_build/results?buildId=1843344&view=ms.vss-test-web.build-test-results-tab
https://dev.azure.com/dnceng/public/_build/results?buildId=1832137&view=ms.vss-test-web.build-test-results-tab
https://dev.azure.com/dnceng/public/_build/results?buildId=1840992&view=ms.vss-test-web.build-test-results-tab

[dotnet-issue-labeler]

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

[ghost]

Tagging subscribers to this area: @JulieLeeMSFT, @jakobbotsch
See info in area-owners.md if you want to be subscribed.

Issue Details

---

This test seems to be failing on all outerloop runtime-coreclr pgo pipelines

Unhandled exception. System.Exception: Condition 'Saw the ThreadPoolIOPack event' is not true
at Tracing.Tests.Common.Assert.True(String name, Boolean condition)
at Tracing.Tests.NativeRuntimeEventSourceTest.Main(String[] args)

Fails in various PRs, e.g.:
https://dev.azure.com/dnceng/public/_build/results?buildId=1843344&view=ms.vss-test-web.build-test-results-tab
https://dev.azure.com/dnceng/public/_build/results?buildId=1832137&view=ms.vss-test-web.build-test-results-tab
https://dev.azure.com/dnceng/public/_build/results?buildId=1840992&view=ms.vss-test-web.build-test-results-tab

Author:	EgorBo
Assignees:	-
Labels:	area-CodeGen-coreclr, untriaged
Milestone:	-

[AndyAyersMS]

I'll take a look.

[AndyAyersMS]

I can't repro this locally yet either running the full pri-1 suite or running just this wrapper. May be some kind of timing issue with other concurrent tests so I will keep trying.

CI logs show the IOPack event is emitted.

        [Simple] ThreadID = 8584 ID = 65 Name = ThreadPoolIOPack
        TimeStamp: 6/29/2022 12:04:01 PM
        LocalTime: 6/29/2022 12:04:03 PM
        Difference: 00:00:02.3316022
        Name = "NativeOverlapped" Value = "150706496"
        Name = "Overlapped" Value = "89279024"
        Name = "ClrInstanceID" Value = "0"

not sure why it is not recognized.

[EgorBo]

I'll try to reproduce it locally too, it seems it's a quite stable fail on CI - https://dev.azure.com/dnceng/public/_build?definitionId=1000

[AndyAyersMS]

I can repro if the machine is loaded (eg run the single test case while the machine running a build in a different clone of the runtime repo).

c:\repos\runtime1\artifacts\tests\coreclr\windows.x86.Checked\Tests\Core_Root\corerun.exe nativeruntimeeventsource.dll  1>D:\bugs\r71331\test1.log
Unhandled exception. System.Exception: Condition 'Saw the ThreadPoolIOPack event' is not true
   at Tracing.Tests.Common.Assert.True(String name, Boolean condition) in C:\repos\runtime1\src\tests\tracing\common\Assert.cs:line 14
   at Tracing.Tests.NativeRuntimeEventSourceTest.Main(String[] args) in C:\repos\runtime1\src\tests\tracing\runtimeeventsource\NativeRuntimeEventSourceTest.cs:line 48

c:\repos\runtime1\artifacts\tests\coreclr\windows.x86.Checked\tracing\runtimeeventsource\nativeruntimeeventsource>echo ERRORLEVEL=-532462766

Pretty sure it's just a timing issue with the test

runtime/src/tests/tracing/runtimeeventsource/NativeRuntimeEventSourceTest.cs

Lines 30 to 49 in 6a02d5d

	// If on Windows, attempt some Overlapped IO (triggers ThreadPool events)
	if (OperatingSystem.IsWindows())
	DoOverlappedIO();
	// Wait for events.
	Thread.Sleep(1000);
	// Generate some GC events.
	GC.Collect(2, GCCollectionMode.Forced);
	// Wait for more events.
	Thread.Sleep(1000);
	// Ensure that we've seen some events.
	foreach (string s in listener.SeenProvidersAndEvents)
	Console.WriteLine(s);
	Assert.True("listener.EventCount > 0", listener.EventCount > 0);
	if (OperatingSystem.IsWindows())
	Assert.True("Saw the ThreadPoolIOPack event", listener.SeenProvidersAndEvents.Contains("Microsoft-Windows-DotNETRuntime/EVENTID(65)"));
	}

In the "good" runs we have

[Simple] ThreadID = 18116 ID = 65 Name = ThreadPoolIOPack
TimeStamp: 6/29/2022 5:56:35 PM
LocalTime: 6/29/2022 5:56:37 PM
Difference: 00:00:01.4429606
	Name = "NativeOverlapped" Value = "148986208"
	Name = "Overlapped" Value = "87809744"
	Name = "ClrInstanceID" Value = "4"

and in the bad one

[Simple] ThreadID = 12144 ID = 65 Name = ThreadPoolIOPack
TimeStamp: 6/29/2022 5:54:01 PM
LocalTime: 6/29/2022 5:54:04 PM
Difference: 00:00:02.7299304
	Name = "NativeOverlapped" Value = "156569912"
	Name = "Overlapped" Value = "95742188"
	Name = "ClrInstanceID" Value = "4"

I think the event needs to arrive within 2 seconds and in the bad case it takes 2.7 seconds.

@tommcdon can you suggest somebody to verify/refute that this is a timing issue?

[AndyAyersMS]

Also see what may be related timing issues: #70966, #68690

[AndyAyersMS]

@tommcdon can you suggest somebody to verify/refute that this is a timing issue?

@tommcdon ping

[tommcdon]

@tommcdon can you suggest somebody to verify/refute that this is a timing issue?
Sorry! I wasn't getting the notifications for this and didn't mean to miss this. @davmason could you take a look?

[davmason]

I verified on my machine that I hit it almost 100% when the machine was at 100 CPU usage, and after the fix in #72010 it passes every time.

The only way this could not be a timing issue is if somehow the JIT recognizes that the code here doesn't actually do anything and removes it. From my understanding that is not currently something the JIT would do.

runtime/src/tests/tracing/runtimeeventsource/NativeRuntimeEventSourceTest.cs

Lines 72 to 79 in 246f245

	private static unsafe void DoOverlappedIO()
	{
	Console.WriteLine("DOOVERLAPPEDIO");
	Overlapped overlapped = new();
	NativeOverlapped* pOverlap = overlapped.Pack(null, null);
	Overlapped.Free(pOverlap);
	}
	}