Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix ELT profiler tests #44285

Merged
merged 4 commits into from
Nov 6, 2020
Merged

Fix ELT profiler tests #44285

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
490df3d
make profiler runner logging more helpful
davmason Nov 4, 2020
dc15a05
prevent ELT from running after shutdown
davmason Nov 5, 2020
2cb121c
fix linux build and code review feedback
davmason Nov 5, 2020
5739d41
update name of method
davmason Nov 6, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
20 changes: 14 additions & 6 deletions src/tests/profiler/common/ProfilerTestRunner.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -83,17 +83,25 @@ public static int Run(string profileePath,
process.BeginOutputReadLine();

process.WaitForExit();
if (process.ExitCode == 100 && verifier.HasPassingOutput)
{
return 100;
}
else

// There are two conditions for profiler tests to pass, the output of the profiled program
// must contain the phrase "PROFILER TEST PASSES" and the return code must be 100. This is
// because lots of verification happen in the profiler code, where it is hard to change the
// program return value.

if (!verifier.HasPassingOutput)
{
LogTestFailure("Profiler tests are expected to contain the text \'" + verifier.SuccessPhrase + "\' in the console output " +
"of the profilee app to indicate a passing test. Usually it is printed from the Shutdown() method of the profiler implementation. This " +
"text was not found in the output above.");
return process.ExitCode == 100 ? process.ExitCode : -1;
}

if (process.ExitCode != 100)
{
LogTestFailure($"Profilee returned exit code {process.ExitCode} instead of expected exit code 100.");
}

return 100;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sure, I added a comment

Copy link
Member

@noahfalk noahfalk Nov 6, 2020 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Precisely unclear

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks

}

private static string GetProfilerPath()
Expand Down
70 changes: 70 additions & 0 deletions src/tests/profiler/native/eltprofiler/slowpatheltprofiler.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,11 +8,14 @@
#include <cctype>
#include <iomanip>
#include <algorithm>
#include <thread>
#include <chrono>

using std::shared_ptr;
using std::vector;
using std::wcout;
using std::endl;
using std::atomic;

shared_ptr<SlowPathELTProfiler> SlowPathELTProfiler::s_profiler;

Expand All @@ -24,18 +27,81 @@ shared_ptr<SlowPathELTProfiler> SlowPathELTProfiler::s_profiler;
#define PROFILER_STUB EXTERN_C void STDMETHODCALLTYPE
#endif // WIN32

class ELTGuard
{
private:
static atomic<bool> s_preventHooks;
static atomic<int> s_hooksInProgress;

public:
ELTGuard()
{
++s_hooksInProgress;
}

~ELTGuard()
{
--s_hooksInProgress;
}

static void Initialize()
{
s_preventHooks = false;
s_hooksInProgress = 0;
}

static bool HasShutdownStarted()
{
return s_preventHooks.load();
}

static void WaitForInProgressHooks()
{
s_preventHooks = true;

while (s_hooksInProgress.load() > 0)
{
std::this_thread::sleep_for(std::chrono::milliseconds(10));
}
}
};

atomic<bool> ELTGuard::s_preventHooks;
atomic<int> ELTGuard::s_hooksInProgress;

PROFILER_STUB EnterStub(FunctionIDOrClientID functionId, COR_PRF_ELT_INFO eltInfo)
{
ELTGuard();

if (ELTGuard::HasShutdownStarted())
{
return;
}

SlowPathELTProfiler::s_profiler->EnterCallback(functionId, eltInfo);
}

PROFILER_STUB LeaveStub(FunctionIDOrClientID functionId, COR_PRF_ELT_INFO eltInfo)
{
ELTGuard();

if (ELTGuard::HasShutdownStarted())
{
return;
}

SlowPathELTProfiler::s_profiler->LeaveCallback(functionId, eltInfo);
}

PROFILER_STUB TailcallStub(FunctionIDOrClientID functionId, COR_PRF_ELT_INFO eltInfo)
{
ELTGuard();

if (ELTGuard::HasShutdownStarted())
{
return;
}

SlowPathELTProfiler::s_profiler->TailcallCallback(functionId, eltInfo);
}

Expand All @@ -50,6 +116,8 @@ HRESULT SlowPathELTProfiler::Initialize(IUnknown* pICorProfilerInfoUnk)
{
Profiler::Initialize(pICorProfilerInfoUnk);

ELTGuard::Initialize();

HRESULT hr = S_OK;
constexpr ULONG bufferSize = 1024;
ULONG envVarLen = 0;
Expand Down Expand Up @@ -109,6 +177,8 @@ HRESULT SlowPathELTProfiler::Initialize(IUnknown* pICorProfilerInfoUnk)

HRESULT SlowPathELTProfiler::Shutdown()
{
ELTGuard::WaitForInProgressHooks();

Profiler::Shutdown();

if (_testType == TestType::EnterHooks)
Expand Down