Skip to content

Commit

Permalink
Add tests for notification profilers (#57429)
Browse files Browse the repository at this point in the history
Add CI tests for notification profilers, and fix a couple things to make life with multiple profilers easier
  * Reduced default timeout for profiler detach - we used to try at 300ms, 600ms, 5s, 10s, and then 10 minutes. The check is just a read of an int, so there's no reason to wait 10 minutes
  * Got rid of a couple asserts that were wrong since switching from the dedicated profiler attach thread to the diagnostics server implementation
  * ProfControlBlock::GetProfilerInfo would only work for active profilers, not attaching profilers, which could cause subtle bugs
  • Loading branch information
davmason authored Aug 17, 2021
1 parent 80c7acc commit e9e9f10
Show file tree
Hide file tree
Showing 30 changed files with 355 additions and 105 deletions.
46 changes: 23 additions & 23 deletions src/coreclr/dlls/mscorrc/mscorrc.rc
Original file line number Diff line number Diff line change
Expand Up @@ -726,29 +726,29 @@ END
// Profiler messages for event log
STRINGTABLE DISCARDABLE
BEGIN
IDS_E_PROF_BAD_PATH "Loading profiler failed. COR_ENABLE_PROFILING and COR_PROFILER were set properly, but COR_PROFILER_PATH was not. COR_PROFILER_PATH must be set to the full path of the profiler DLL to load with no more than 260 charaters including the null terminator."
IDS_E_PROF_NO_CLSID "Loading profiler failed. COR_ENABLE_PROFILING was set properly, but COR_PROFILER was not. COR_PROFILER must be set to the CLSID of the profiler to load."
IDS_E_PROF_INTERNAL_INIT "Loading profiler failed due to an internal profiling services initialization failure. Profiler CLSID: '%s'. HRESULT: 0x%x."
IDS_E_PROF_BAD_CLSID "Loading profiler failed. COR_PROFILER is set to an invalid CLSID: '%s'. HRESULT: 0x%x."
IDS_E_PROF_NO_CALLBACK_IFACE "Loading profiler failed. COR_PROFILER is set to a CLSID of a COM object that does not implement the interface GUID (IID) requested by the CLR. This often indicates that the profiler does not support this version of the CLR. Profiler CLSID: '%s'. Requested IID: '%s'."
IDS_E_PROF_CCI_FAILED "Loading profiler failed during CoCreateInstance. Profiler CLSID: '%s'. HRESULT: 0x%x."
IDS_E_PROF_INIT_CALLBACK_FAILED "Loading profiler failed. The profiler COM object was instantiated, but the profiler failed during its initialization callback. Profiler CLSID: '%s'. HRESULT: 0x%x."
IDS_PROF_SUPPLEMENTARY_INFO "Process ID (decimal): %d. Message ID: [0x%x]."
IDS_PROF_LOAD_COMPLETE "The profiler was loaded successfully. Profiler CLSID: '%s'."
IDS_E_PROF_NOT_ATTACHABLE "Loading profiler failed. The profiler COM object was instantiated, but the profiler does not support attaching to a live process. The profiler must be loaded at application startup by using a launcher program included with the profiler (if any) or by setting the COR_ENABLE_PROFILING and COR_PROFILER environment variables before launching the application to be profiled. Profiler CLSID: '%s'"
IDS_E_PROF_UNHANDLED_EXCEPTION_ON_LOAD "Loading profiler failed. There was an unhandled exception while trying to instantiate the profiler COM object. Please ensure the CLSID is associated with a valid profiler designed to work with this version of the runtime. Profiler CLSID: '%s'."
IDS_PROF_ATTACH_REQUEST_RECEIVED "The CLR received a request to attach a profiler. Profiler CLSID: '%s'."
IDS_PROF_DETACH_INITIATED "The profiler currently in use has requested to be detached from the process. The CLR has disabled communication with the profiler and will unload the profiler when it is safe to do so."
IDS_PROF_DETACH_COMPLETE "The CLR has fully detached and unloaded the profiler."
IDS_PROF_DETACH_THREAD_ERROR "There was an internal failure in the profiling API detach infrastructure. The profiler will not be able to be detached. Error code: %d."
IDS_PROF_CANCEL_ACTIVATION "The profiler has requested that the CLR instance not load the profiler into this process. Profiler CLSID: '%s'."
IDS_PROF_V2PROFILER_DISABLED "Loading profiler failed. The profiler that was configured to load was designed for an older version of the CLR. You can use the COMPlus_ProfAPI_ProfilerCompatibilitySetting environment variable to allow older profilers to be loaded by the current version of the CLR. Please consult the documentation for information on how to use this environment variable, and the risks associated with it. Profiler CLSID: '%s'."
IDS_PROF_V2PROFILER_ENABLED "A profiler designed for an older version of the CLR was loaded because of the environment variable setting below. Older profilers will continue to work in many cases, but if you encounter problems, please consider upgrading the profiler or changing the setting of the environment variable. Please consult the documentation for information on how to use this environment variable, and the risks associated with it. Environment variable setting: %s=%s. Profiler CLSID: '%s'."
IDS_PROF_PROFILER_DISABLED "Profilers will not be loaded by the current version of the CLR because of the environment variable setting below. Please consult the documentation for information on how to use this environment variable, and the risks associated with it. Environment variable setting: %s=%s. Profiler CLSID: '%s'."
IDS_E_PROF_NOTIFICATION_DISABLED "Profiler was prevented from loading notification profiler due to app settings."
IDS_E_PROF_NOTIFICATION_LIMIT_EXCEEDED "Notification profiler was prevented from loading because the limit of notification profilers was reached."
IDS_E_PROF_TIMEOUT_WAITING_FOR_CONCURRENT_GC "Profiler timed out on waiting for concurrent GC to finish after '%d' milliseconds. Please configure your profiler to increase its attaching time out value or consult the documentation for the COMPlus_ProfAPI_AttachProfilerMinTimeoutInMs environment variable and try again. Profiler CLSID: '%s'."
IDS_PROF_ALREADY_LOADED "A request was made to load a profiler when a profiler was already loaded."
IDS_E_PROF_BAD_PATH "Loading profiler failed. COR_ENABLE_PROFILING and COR_PROFILER were set properly, but COR_PROFILER_PATH was not. COR_PROFILER_PATH must be set to the full path of the profiler DLL to load with no more than 260 charaters including the null terminator.\n"
IDS_E_PROF_NO_CLSID "Loading profiler failed. COR_ENABLE_PROFILING was set properly, but COR_PROFILER was not. COR_PROFILER must be set to the CLSID of the profiler to load.\n"
IDS_E_PROF_INTERNAL_INIT "Loading profiler failed due to an internal profiling services initialization failure. Profiler CLSID: '%s'. HRESULT: 0x%x.\n"
IDS_E_PROF_BAD_CLSID "Loading profiler failed. COR_PROFILER is set to an invalid CLSID: '%s'. HRESULT: 0x%x.\n"
IDS_E_PROF_NO_CALLBACK_IFACE "Loading profiler failed. COR_PROFILER is set to a CLSID of a COM object that does not implement the interface GUID (IID) requested by the CLR. This often indicates that the profiler does not support this version of the CLR. Profiler CLSID: '%s'. Requested IID: '%s'.\n"
IDS_E_PROF_CCI_FAILED "Loading profiler failed during CoCreateInstance. Profiler CLSID: '%s'. HRESULT: 0x%x.\n"
IDS_E_PROF_INIT_CALLBACK_FAILED "Loading profiler failed. The profiler COM object was instantiated, but the profiler failed during its initialization callback. Profiler CLSID: '%s'. HRESULT: 0x%x.\n"
IDS_PROF_SUPPLEMENTARY_INFO "Process ID (decimal): %d. Message ID: [0x%x].\n"
IDS_PROF_LOAD_COMPLETE "The profiler was loaded successfully. Profiler CLSID: '%s'.\n"
IDS_E_PROF_NOT_ATTACHABLE "Loading profiler failed. The profiler COM object was instantiated, but the profiler does not support attaching to a live process. The profiler must be loaded at application startup by using a launcher program included with the profiler (if any) or by setting the COR_ENABLE_PROFILING and COR_PROFILER environment variables before launching the application to be profiled. Profiler CLSID: '%s'\n"
IDS_E_PROF_UNHANDLED_EXCEPTION_ON_LOAD "Loading profiler failed. There was an unhandled exception while trying to instantiate the profiler COM object. Please ensure the CLSID is associated with a valid profiler designed to work with this version of the runtime. Profiler CLSID: '%s'.\n"
IDS_PROF_ATTACH_REQUEST_RECEIVED "The CLR received a request to attach a profiler. Profiler CLSID: '%s'.\n"
IDS_PROF_DETACH_INITIATED "The profiler currently in use has requested to be detached from the process. The CLR has disabled communication with the profiler and will unload the profiler when it is safe to do so.\n"
IDS_PROF_DETACH_COMPLETE "The CLR has fully detached and unloaded the profiler.\n"
IDS_PROF_DETACH_THREAD_ERROR "There was an internal failure in the profiling API detach infrastructure. The profiler will not be able to be detached. Error code: %d.\n"
IDS_PROF_CANCEL_ACTIVATION "The profiler has requested that the CLR instance not load the profiler into this process. Profiler CLSID: '%s'.\n"
IDS_PROF_V2PROFILER_DISABLED "Loading profiler failed. The profiler that was configured to load was designed for an older version of the CLR. You can use the COMPlus_ProfAPI_ProfilerCompatibilitySetting environment variable to allow older profilers to be loaded by the current version of the CLR. Please consult the documentation for information on how to use this environment variable, and the risks associated with it. Profiler CLSID: '%s'.\n"
IDS_PROF_V2PROFILER_ENABLED "A profiler designed for an older version of the CLR was loaded because of the environment variable setting below. Older profilers will continue to work in many cases, but if you encounter problems, please consider upgrading the profiler or changing the setting of the environment variable. Please consult the documentation for information on how to use this environment variable, and the risks associated with it. Environment variable setting: %s=%s. Profiler CLSID: '%s'.\n"
IDS_PROF_PROFILER_DISABLED "Profilers will not be loaded by the current version of the CLR because of the environment variable setting below. Please consult the documentation for information on how to use this environment variable, and the risks associated with it. Environment variable setting: %s=%s. Profiler CLSID: '%s'.\n"
IDS_E_PROF_NOTIFICATION_DISABLED "Profiler was prevented from loading notification profiler due to app settings.\n"
IDS_E_PROF_NOTIFICATION_LIMIT_EXCEEDED "Notification profiler was prevented from loading because the limit of notification profilers was reached.\n"
IDS_E_PROF_TIMEOUT_WAITING_FOR_CONCURRENT_GC "Profiler timed out on waiting for concurrent GC to finish after '%d' milliseconds. Please configure your profiler to increase its attaching time out value or consult the documentation for the COMPlus_ProfAPI_AttachProfilerMinTimeoutInMs environment variable and try again. Profiler CLSID: '%s'.\n"
IDS_PROF_ALREADY_LOADED "A request was made to load a profiler when a profiler was already loaded.\n"
END


Expand Down
2 changes: 1 addition & 1 deletion src/coreclr/inc/profilepriv.h
Original file line number Diff line number Diff line change
Expand Up @@ -110,7 +110,7 @@ class ProfilerInfo
EventMask eventMask;

//---------------------------------------------------------------
// m_dwProfilerEvacuationCounter keeps track of how many profiler
// dwProfilerEvacuationCounter keeps track of how many profiler
// callback calls remain on the stack
//---------------------------------------------------------------
// Why volatile?
Expand Down
2 changes: 1 addition & 1 deletion src/coreclr/inc/profilepriv.inl
Original file line number Diff line number Diff line change
Expand Up @@ -168,7 +168,7 @@ inline BOOL ProfControlBlock::IsMainProfiler(ProfToEEInterfaceImpl *pProfToEE)
inline ProfilerInfo *ProfControlBlock::GetProfilerInfo(ProfToEEInterfaceImpl *pProfToEE)
{
ProfilerInfo *pProfilerInfo = NULL;
IterateProfilers(ProfilerCallbackType::Active,
IterateProfilers(ProfilerCallbackType::ActiveOrInitializing,
[](ProfilerInfo *pProfilerInfo, ProfToEEInterfaceImpl *pProfToEE, ProfilerInfo **ppFoundProfilerInfo)
{
if (pProfilerInfo->pProfInterface->m_pProfToEE == pProfToEE)
Expand Down
11 changes: 0 additions & 11 deletions src/coreclr/vm/eetoprofinterfaceimpl.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -637,9 +637,6 @@ HRESULT EEToProfInterfaceImpl::CreateProfiler(
}
CONTRACTL_END;

// Always called before Thread created.
_ASSERTE(GetThreadNULLOk() == NULL);

// Try and CoCreate the registered profiler
ReleaseHolder<ICorProfilerCallback2> pCallback2;
HModuleHolder hmodProfilerDLL;
Expand Down Expand Up @@ -2771,10 +2768,6 @@ HRESULT EEToProfInterfaceImpl::InitializeForAttach(void * pvClientData, UINT cbC

_ASSERTE(m_pProfToEE != NULL);

// Attach initialization occurs on the AttachThread, which does not have an EEThread
// object
_ASSERTE(GetThreadNULLOk() == NULL);

// Should only be called on profilers that support ICorProfilerCallback3
_ASSERTE(m_pCallback3 != NULL);

Expand Down Expand Up @@ -2826,10 +2819,6 @@ HRESULT EEToProfInterfaceImpl::ProfilerAttachComplete()
LL_INFO10,
"**PROF: Calling profiler's ProfilerAttachComplete() method.\n"));

// Attach initialization occurs on the AttachThread, which does not have an EEThread
// object
_ASSERTE(GetThreadNULLOk() == NULL);

// Should only be called on profilers that support ICorProfilerCallback3
_ASSERTE(m_pCallback3 != NULL);

Expand Down
8 changes: 4 additions & 4 deletions src/coreclr/vm/profdetach.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -170,9 +170,9 @@ HRESULT ProfilingAPIDetach::RequestProfilerDetach(ProfilerInfo *pProfilerInfo, D

if (dwExpectedCompletionMilliseconds == 0)
{
// Pick suitable default if the profiler just leaves this at 0. 5 seconds is
// Pick suitable default if the profiler just leaves this at 0. 2.5 seconds is
// reasonable.
dwExpectedCompletionMilliseconds = 5000;
dwExpectedCompletionMilliseconds = 2500;
}

{
Expand Down Expand Up @@ -365,8 +365,8 @@ void ProfilingAPIDetach::SleepWhileProfilerEvacuates(ProfilerDetachInfo *pDetach
const DWORD kdwDefaultMinSleepMs = 300;

// The default "steady state" max sleep is how long we'll wait if, after a couple
// tries the profiler still hasn't evacuated. Default to every 10 minutes
const DWORD kdwDefaultMaxSleepMs = 600000;
// tries the profiler still hasn't evacuated. Default to every 5 seconds
const DWORD kdwDefaultMaxSleepMs = 5000;

static DWORD s_dwMinSleepMs = 0;
static DWORD s_dwMaxSleepMs = 0;
Expand Down
6 changes: 4 additions & 2 deletions src/coreclr/vm/proftoeeinterfaceimpl.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -9545,14 +9545,16 @@ HRESULT ProfToEEInterfaceImpl::RequestProfilerDetach(DWORD dwExpectedCompletionM
}
CONTRACTL_END;

PROFILER_TO_CLR_ENTRYPOINT_SYNC_EX(
PROFILER_TO_CLR_ENTRYPOINT_ASYNC_EX(
kP2EEAllowableAfterAttach | kP2EETriggers,
(LF_CORPROF,
LL_INFO1000,
"**PROF: RequestProfilerDetach.\n"));

#ifdef FEATURE_PROFAPI_ATTACH_DETACH
return ProfilingAPIDetach::RequestProfilerDetach(g_profControlBlock.GetProfilerInfo(this), dwExpectedCompletionMilliseconds);
ProfilerInfo *pProfilerInfo = g_profControlBlock.GetProfilerInfo(this);
_ASSERTE(pProfilerInfo != NULL);
return ProfilingAPIDetach::RequestProfilerDetach(pProfilerInfo, dwExpectedCompletionMilliseconds);
#else // FEATURE_PROFAPI_ATTACH_DETACH
return E_NOTIMPL;
#endif // FEATURE_PROFAPI_ATTACH_DETACH
Expand Down
33 changes: 29 additions & 4 deletions src/tests/profiler/common/ProfilerTestRunner.cs
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,8 @@

namespace Profiler.Tests
{
public delegate void ProfilerCallback();

[Flags]
public enum ProfileeOptions
{
Expand All @@ -27,7 +29,9 @@ public static int Run(string profileePath,
string profileeArguments = "",
ProfileeOptions profileeOptions = ProfileeOptions.None,
Dictionary<string, string> envVars = null,
string reverseServerName = null)
string reverseServerName = null,
bool loadAsNotification = false,
int notificationCopies = 1)
{
string arguments;
string program;
Expand All @@ -44,8 +48,29 @@ public static int Run(string profileePath,
if (!profileeOptions.HasFlag(ProfileeOptions.NoStartupAttach))
{
envVars.Add("CORECLR_ENABLE_PROFILING", "1");
envVars.Add("CORECLR_PROFILER_PATH", profilerPath);
envVars.Add("CORECLR_PROFILER", "{" + profilerClsid + "}");

if (loadAsNotification)
{
StringBuilder builder = new StringBuilder();
for(int i = 0; i < notificationCopies; ++i)
{
builder.Append(profilerPath);
builder.Append("=");
builder.Append("{");
builder.Append(profilerClsid.ToString());
builder.Append("}");
builder.Append(";");
}

envVars.Add("CORECLR_ENABLE_NOTIFICATION_PROFILERS", "1");
envVars.Add("CORECLR_NOTIFICATION_PROFILERS", builder.ToString());

}
else
{
envVars.Add("CORECLR_PROFILER", "{" + profilerClsid + "}");
envVars.Add("CORECLR_PROFILER_PATH", profilerPath);
}
}

if (profileeOptions.HasFlag(ProfileeOptions.OptimizationSensitive))
Expand Down Expand Up @@ -123,7 +148,7 @@ public static int Run(string profileePath,
return 100;
}

private static string GetProfilerPath()
public static string GetProfilerPath()
{
string profilerName;
if (TestLibrary.Utilities.IsWindows)
Expand Down
60 changes: 60 additions & 0 deletions src/tests/profiler/multiple/multiple.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,60 @@
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.

using System;
using System.Runtime.CompilerServices;
using System.Runtime.InteropServices;
using System.Threading;

namespace Profiler.Tests
{
class MultiplyLoaded
{
static readonly Guid MultipleProfilerGuid = new Guid("BFA8EF13-E144-49B9-B95C-FC1C150C7651");
static readonly string ProfilerPath = ProfilerTestRunner.GetProfilerPath();

[DllImport("Profiler")]
private static extern void PassCallbackToProfiler(ProfilerCallback callback);

public static int RunTest(String[] args)
{
ManualResetEvent _profilerDone = new ManualResetEvent(false);
PassCallbackToProfiler(() => _profilerDone.Set());

ProfilerControlHelpers.AttachProfilerToSelf(MultipleProfilerGuid, ProfilerPath);

try
{
Console.WriteLine("Throwing exception");
throw new Exception("Test exception!");
}
catch
{
// intentionally swallow the exception
Console.WriteLine("Exception caught");
}

Console.WriteLine("Waiting for profilers to all detach");
if (!_profilerDone.WaitOne(TimeSpan.FromMinutes(5)))
{
Console.WriteLine("Profiler did not set the callback, test will fail.");
}

return 100;
}

public static int Main(string[] args)
{
if (args.Length > 0 && args[0].Equals("RunTest", StringComparison.OrdinalIgnoreCase))
{
return RunTest(args);
}

return ProfilerTestRunner.Run(profileePath: System.Reflection.Assembly.GetExecutingAssembly().Location,
testName: "MultiplyLoaded",
profilerClsid: MultipleProfilerGuid,
loadAsNotification: true,
notificationCopies: 2);
}
}
}
15 changes: 15 additions & 0 deletions src/tests/profiler/multiple/multiple.csproj
Original file line number Diff line number Diff line change
@@ -0,0 +1,15 @@
<Project Sdk="Microsoft.NET.Sdk">
<PropertyGroup>
<TargetFrameworkIdentifier>.NETCoreApp</TargetFrameworkIdentifier>
<OutputType>exe</OutputType>
<CLRTestKind>BuildAndRun</CLRTestKind>
<AllowUnsafeBlocks>true</AllowUnsafeBlocks>
<CLRTestPriority>0</CLRTestPriority>
</PropertyGroup>
<ItemGroup>
<Compile Include="$(MSBuildProjectName).cs" />
<ProjectReference Include="$(TestSourceDir)Common/CoreCLRTestLibrary/CoreCLRTestLibrary.csproj" />
<ProjectReference Include="../common/profiler_common.csproj" />
<ProjectReference Include="$(MSBuildThisFileDirectory)/../native/CMakeLists.txt" />
</ItemGroup>
</Project>
Loading

0 comments on commit e9e9f10

Please sign in to comment.