Fix ELT profiler tests

[davmason]

Fixes #44055

Recently profiler/elt/slowpatheltenter/slowpatheltenter started failing. On investigation it was because a timer firing was triggering managed code to run as the runtime was shutting down, and we would occasionally try to use pCorProfilerInfo after it was set to NULL.

This PR add some synchronization so we bail on the ELT hooks once Shutdown is called. It also changes the output when a test fails, the previous wording was confusing because it implied PROFILER_TEST_PASSES in the output was the only thing necessary for a test to pass when we check the exit code of the process as well.

[ghost]

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

[stephentoub]

Recently profiler/elt/slowpatheltenter/slowpatheltenter started failing

What changed? You mention a timer firing; it wasn't before?

I'm asking because we saw some other diagnostic failures start frequently around the same time, e.g. #44037, and I'm wondering if there might be a link.

[sdmaclea]

LGTM

[sdmaclea]

I think you said in an earlier PR that the exit code didn't matter for profiler tests. It still would be nice to have a comment to that effect.

[davmason]

I don't remember exactly what I said, but I think I was trying to say that the exit code doesn't matter for that particular test. We do check the exit code, it's just that a lot of profiler tests don't use it to indicate failure. Some of them do, however, and crashes will return a non 100 exit code.

[sdmaclea]

I guess I just wanted to make it clear to someone other than you that return 100; can happen even though the test failed. I just feels confusing to me. If we hadn't talked about it, I would have asked again.

[davmason]

Sure, I added a comment

[noahfalk]

I agree that logging a failure message and then returning 100 feels counter intuitive. If the exit code matters I was expecting there would be some conditional logic or if it doesn't matter then perhaps we should return 0?

EDIT: nm, I see that LogTestFailure() also throws an exception so 100 is only what happens in the success case.

[davmason]

I misunderstood what Steve was saying. As Noah points out in the edit above LogTestFailure intentionally throws an unhandled exception to fail the test. I can see how that is unclear to others though, since it just says log in the name

[sdmaclea]

Precisely unclear

[davmason]

I just changed it from LogTestFailure to FailFastWithMessage so hopefully its more clear just from the name

[sdmaclea]

Thanks

[davmason]

Recently profiler/elt/slowpatheltenter/slowpatheltenter started failing

What changed? You mention a timer firing; it wasn't before?

I shouldn't have worded it so strongly. I was inferring something changed due to it only recently starting to fail, but have no proof. These tests register enter/leave hooks through the profiler APIs, and recently they started failing where after the profiler shut down and cleaned up resources some background thread would still be calling managed code and the test would AV trying to use pCorProfilerInfo, which is now null.

When I debugged, it consistently hit in a managed timer callback but I never actually verified what code path was hitting it. For the purposes of this test the exact code that causes the failure is irrelevant, it has always been legal and possible for other threads to continue running during shutdown. This is one of those "I'm surprised this worked until now" moments.

I will take a look to see if there is an obvious change causing this, but I would be pretty surprised if this was related to the other failing tests you linked.

[davmason]

It fails before it gets to anything that actually tells me what timer is firing:

(lldb) clrstack
OS Thread Id: 0x1abfd9 (10)
        Child SP               IP Call Site
00007FFFF40624E0 00007ffff4684bfa [HelperMethodFrame: 00007ffff40624e0]
00007FFFF4062800 00007FFF7DFDD6A9 System.Threading.PortableThreadPool+GateThread.EnsureRunning(System.Threading.PortableThreadPool)
00007FFFF4062830 00007FFF7DFD57D9 System.Threading.PortableThreadPool.RequestWorker()
00007FFFF4062860 00007FFF7DFD121E System.Threading.ThreadPool.RequestWorkerThread()
00007FFFF40628F0 00007FFF7DFD06D6 System.Threading.ThreadPoolWorkQueue.EnqueueTimeSensitiveWorkItem(System.Threading.IThreadPoolWorkItem)
00007FFFF4062920 00007FFF7DFD05F5 System.Threading.ThreadPool.UnsafeQueueTimeSensitiveWorkItemInternal(System.Threading.IThreadPoolWorkItem)
00007FFFF4062950 00007FFF7DFBC850 System.Threading.ThreadPool.UnsafeQueueUnmanagedWorkItem(IntPtr, IntPtr)

But, although it mainly fails in the timer path it also randomly fails in other codepaths too. I don't know what changed but it's very unlikely that this is anything but a test bug.

[davmason]

It occurs to me that the reason we're seeing managed code executing at times when it wasn't before is the portable thread pool work that @kouvel enabled recently. Earlier I said I didn't know what was causing the timer, but I think the new thread pool implementation itself is causing it.

[noahfalk]

LGTM

[kouvel]

It occurs to me that the reason we're seeing managed code executing at times when it wasn't before is the portable thread pool work that @kouvel enabled recently. Earlier I said I didn't know what was causing the timer, but I think the new thread pool implementation itself is causing it.

Tiered compilation's background work currently uses the thread pool, a timer is used to get a thread pool thread and some new managed code is triggered.