[Profiler] Make timer_create-based CPU profiler default (#7322)

Author: gleocadie

profiler/build/CpuWallTime.linux.json

@@ -26,6 +26,7 @@
         "DD_PROFILING_ENABLED": "1",
         "DD_PROFILING_CPU_ENABLED": "1",
         "DD_INTERNAL_USE_BACKTRACE2": "1",
+        "DD_INTERNAL_CPU_PROFILER_TYPE": "TimerCreate",
         "DD_TRACE_ENABLED" : "0"
       }
     },
@@ -35,17 +36,19 @@
         "DD_CLR_ENABLE_NGEN": "true",
         "DD_PROFILING_ENABLED": "1",
         "DD_PROFILING_CPU_ENABLED": "1",
+        "DD_INTERNAL_CPU_PROFILER_TYPE": "TimerCreate",
         "DD_INTERNAL_USE_BACKTRACE2": "0",
         "DD_TRACE_ENABLED" : "0"
       }
     },
     {
-      "name": "Profiler_cpu_walltime_timer_create",
+      "name": "Profiler_cpu_walltime_manual",
       "environmentVariables": {
         "DD_CLR_ENABLE_NGEN": "true",
         "DD_PROFILING_ENABLED": "1",
         "DD_PROFILING_CPU_ENABLED": "1",
-        "DD_INTERNAL_CPU_PROFILER_TYPE": "TimerCreate",
+        "DD_INTERNAL_USE_BACKTRACE2": "1",
+        "DD_INTERNAL_CPU_PROFILER_TYPE": "ManualCpuTime",
         "DD_TRACE_ENABLED" : "0"
       }
     }

profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/ProfilerSignalManager.cpp

@@ -93,6 +93,22 @@ bool ProfilerSignalManager::UnRegisterHandler()
     return true;
 }
 
+bool ProfilerSignalManager::IgnoreSignal() {
+    struct sigaction sampleAction;
+    sampleAction.sa_handler = SIG_IGN;
+    sigemptyset(&sampleAction.sa_mask);
+    sampleAction.sa_flags = 0;
+
+    int32_t result = sigaction(_signalToSend, &sampleAction, nullptr);
+    if (result != 0)
+    {
+        Log::Error("ProfilerSignalManager::IgnoreSignal: Failed mark ", strsignal(_signalToSend), " as ignored. Reason: ",
+                   strerror(errno), ".");
+        return false;
+    }
+    return true;
+}
+
 void ProfilerSignalManager::SetSignal(int32_t signal)
 {
     _signalToSend = signal;

profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/ProfilerSignalManager.h

@@ -18,6 +18,7 @@ class ProfilerSignalManager
 
     bool RegisterHandler(HandlerFn_t handler);
     bool UnRegisterHandler();
+    bool IgnoreSignal();
     int32_t SendSignal(pid_t threadId);
     bool CheckSignalHandler();
     bool IsHandlerInPlace() const;

profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/TimerCreateCpuProfiler.cpp

@@ -17,7 +17,7 @@
 #include <ucontext.h>
 #include <unistd.h>
 
-TimerCreateCpuProfiler* TimerCreateCpuProfiler::Instance = nullptr;
+std::atomic<TimerCreateCpuProfiler*> TimerCreateCpuProfiler::Instance = nullptr;
 
 TimerCreateCpuProfiler::TimerCreateCpuProfiler(
     IConfiguration* pConfiguration,
@@ -29,7 +29,8 @@ TimerCreateCpuProfiler::TimerCreateCpuProfiler(
     _pSignalManager{pSignalManager}, // put it as parameter for better testing
     _pManagedThreadsList{pManagedThreadsList},
     _pProvider{pProvider},
-    _samplingInterval{pConfiguration->GetCpuProfilingInterval()}
+    _samplingInterval{pConfiguration->GetCpuProfilingInterval()},
+    _nbThreadsInSignalHandler{0}
 {
     Log::Info("Cpu profiling interval: ", _samplingInterval.count(), "ms");
     Log::Info("timer_create Cpu profiler is enabled");
@@ -91,6 +92,15 @@ bool TimerCreateCpuProfiler::StartImpl()
 
 bool TimerCreateCpuProfiler::StopImpl()
 {
+    Instance = nullptr;
+    // we cannot unregister. We would replace the current action by the default one
+    // which will cause the termination of the process
+    // Instead, mark SIGPROF as ignored.
+    if (!_pSignalManager->IgnoreSignal())
+    {
+        Log::Warn("Failed to mark the signal SIGPROF as ignored.");
+    }
+
     {
         std::unique_lock lock(_registerLock);
 
@@ -99,15 +109,27 @@ bool TimerCreateCpuProfiler::StopImpl()
         _pManagedThreadsList->ForEach([this](ManagedThreadInfo* thread) { UnregisterThreadImpl(thread); });
     }
 
-    Instance = nullptr;
-    _pSignalManager->UnRegisterHandler();
+    std::uint64_t nbThreadsInSignalHandler = _nbThreadsInSignalHandler;
+    if (nbThreadsInSignalHandler != 0)
+    {
+        Log::Info("Waiting for all threads exiting the signal handler (#threads ", _nbThreadsInSignalHandler, ")");
+    
+        // TODO: for now we sleep.
+        std::this_thread::sleep_for(500ms);
+        if (_nbThreadsInSignalHandler != 0)
+        {
+            Log::Warn("There are threads that are still executing the signal handler: ", _nbThreadsInSignalHandler);
+            return false;
+        }
+        Log::Info("All threads exited the signal handler");
+    }
 
     return true;
 }
 
 bool TimerCreateCpuProfiler::CollectStackSampleSignalHandler(int sig, siginfo_t* info, void* ucontext)
 {
-    auto instance = Instance;
+    auto instance = Instance.load();
     if (instance == nullptr)
     {
         return false;
@@ -122,7 +144,6 @@ extern "C" unsigned long long dd_inside_wrapped_functions() __attribute__((weak)
 
 bool TimerCreateCpuProfiler::CanCollect(void* ctx)
 {
-    // TODO (in another PR): add metrics about reasons we could not collect
     if (dd_inside_wrapped_functions != nullptr && dd_inside_wrapped_functions() != 0)
     {
         _discardMetrics->Incr<DiscardReason::InsideWrappedFunction>();
@@ -189,12 +210,14 @@ struct StackWalkLock
 
 bool TimerCreateCpuProfiler::Collect(void* ctx)
 {
+    _nbThreadsInSignalHandler++;
     _totalSampling->Incr();
 
     auto threadInfo = ManagedThreadInfo::CurrentThreadInfo;
     if (threadInfo == nullptr)
     {
         _discardMetrics->Incr<DiscardReason::UnknownThread>();
+        _nbThreadsInSignalHandler--;
         // Ooops should never happen
         return false;
     }
@@ -203,11 +226,13 @@ bool TimerCreateCpuProfiler::Collect(void* ctx)
     if (!l.IsLockAcquired())
     {
         _discardMetrics->Incr<DiscardReason::FailedAcquiringLock>();
+        _nbThreadsInSignalHandler--;
         return false;
     }
 
     if (!CanCollect(ctx))
     {
+        _nbThreadsInSignalHandler--;
         return false;
     }
 
@@ -217,6 +242,7 @@ bool TimerCreateCpuProfiler::Collect(void* ctx)
     auto rawCpuSample = _pProvider->GetRawSample();
     if (!rawCpuSample)
     {
+        _nbThreadsInSignalHandler--;
         return false;
     }
 
@@ -229,6 +255,7 @@ bool TimerCreateCpuProfiler::Collect(void* ctx)
     {
         rawCpuSample.Discard();
         _discardMetrics->Incr<DiscardReason::EmptyBacktrace>();
+        _nbThreadsInSignalHandler--;
         return false;
     }
 
@@ -240,6 +267,7 @@ bool TimerCreateCpuProfiler::Collect(void* ctx)
     rawCpuSample->AppDomainId = threadInfo->GetAppDomainId();
     rawCpuSample->ThreadInfo = std::move(threadInfo);
     rawCpuSample->Duration = _samplingInterval;
+    _nbThreadsInSignalHandler--;
     return true;
 }
 

profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/TimerCreateCpuProfiler.h

@@ -42,7 +42,7 @@ class TimerCreateCpuProfiler : public ServiceBase
 
 private:
     static bool CollectStackSampleSignalHandler(int sig, siginfo_t* info, void* ucontext);
-    static TimerCreateCpuProfiler* Instance;
+    static std::atomic<TimerCreateCpuProfiler*> Instance;
 
     bool CanCollect(void* context);
     bool Collect(void* ucontext);
@@ -59,4 +59,5 @@ class TimerCreateCpuProfiler : public ServiceBase
     std::shared_mutex _registerLock;
     std::shared_ptr<CounterMetric> _totalSampling;
     std::shared_ptr<DiscardMetrics> _discardMetrics;
+    std::atomic<std::uint64_t> _nbThreadsInSignalHandler;
 };

profiler/src/ProfilerEngine/Datadog.Profiler.Native/Configuration.cpp

@@ -26,6 +26,12 @@ std::string const Configuration::DefaultEmptyString = "";
 std::chrono::seconds const Configuration::DefaultDevUploadInterval = 20s;
 std::chrono::seconds const Configuration::DefaultProdUploadInterval = 60s;
 std::chrono::milliseconds const Configuration::DefaultCpuProfilingInterval = 9ms;
+CpuProfilerType const Configuration::DefaultCpuProfilerType =
+#ifdef _WINDOWS
+    CpuProfilerType::ManualCpuTime;
+#else
+    CpuProfilerType::TimerCreate;
+#endif
 
 Configuration::Configuration()
 {
@@ -107,7 +113,7 @@ Configuration::Configuration()
         );
     _httpRequestDurationThreshold = ExtractHttpRequestDurationThreshold();
     _forceHttpSampling = GetEnvironmentValue(EnvironmentVariables::ForceHttpSampling, false);
-    _cpuProfilerType = GetEnvironmentValue(EnvironmentVariables::CpuProfilerType, CpuProfilerType::ManualCpuTime);
+    _cpuProfilerType = GetEnvironmentValue(EnvironmentVariables::CpuProfilerType, DefaultCpuProfilerType);
     _isWaitHandleProfilingEnabled = GetEnvironmentValue(EnvironmentVariables::WaitHandleProfilingEnabled, false);
 }
 

profiler/src/ProfilerEngine/Datadog.Profiler.Native/Configuration.h

@@ -120,6 +120,7 @@ class Configuration final : public IConfiguration
     static std::chrono::seconds const DefaultDevUploadInterval;
     static std::chrono::seconds const DefaultProdUploadInterval;
     static std::chrono::milliseconds const DefaultCpuProfilingInterval;
+    static CpuProfilerType const DefaultCpuProfilerType;
 
     bool _isProfilingEnabled;
     bool _isCpuProfilingEnabled;

profiler/src/ProfilerEngine/Datadog.Profiler.Native/CorProfilerCallback.cpp

@@ -72,6 +72,30 @@
 
 #include <cmath>
 
+void LogServiceStart(bool success, const char* name )
+{
+    if (success)
+    {
+        Log::Info(name, " started successfully.");
+    }
+    else
+    {
+        Log::Info(name, " failed to start. This service might have been started earlier.");
+    }
+}
+
+void LogServiceStop(bool success, const char* name )
+{
+    if (success)
+    {
+        Log::Info(name, " stopped successfully.");
+    }
+    else
+    {
+        Log::Info(name, " failed to stopped. This service might have been stopped earlier.");
+    }
+}
+
 IClrLifetime* CorProfilerCallback::GetClrLifetime() const
 {
     return _pClrLifetime.get();
@@ -520,7 +544,9 @@ void CorProfilerCallback::InitializeServices()
 #ifdef LINUX
     if (_pConfiguration->IsCpuProfilingEnabled() && _pConfiguration->GetCpuProfilerType() == CpuProfilerType::TimerCreate)
     {
-        _pCpuProfiler = RegisterService<TimerCreateCpuProfiler>(
+        // Other alternative in case of crash-at-shutdown, do not register it as a service
+        // we will have to start it by hand (already stopped by hand)
+        _pCpuProfiler = std::make_unique<TimerCreateCpuProfiler>(
             _pConfiguration.get(),
             ProfilerSignalManager::Get(SIGPROF),
             _pManagedThreadList,
@@ -714,17 +740,22 @@ bool CorProfilerCallback::StartServices()
     {
         auto name = service->GetName();
         success = service->Start();
-        if (success)
-        {
-            Log::Info(name, " started successfully.");
-        }
-        else
-        {
-            Log::Info(name, " failed to start. This service might have been started earlier.");
-        }
+        LogServiceStart(success, name);
         result &= success;
     }
 
+#ifdef LINUX
+    // We cannot add the timer_create-based CPU profiler to the _services list
+    // we have to control the Stop
+    // If we fail to stop, we mustn't release the memory associated to it
+    // otherwise we might crash.
+    if (_pCpuProfiler != nullptr)
+    {
+        auto success = _pCpuProfiler->Start();
+        LogServiceStart(success, _pCpuProfiler->GetName());
+    }
+#endif
+
     return result;
 }
 
@@ -759,14 +790,7 @@ bool CorProfilerCallback::StopServices()
         const auto& service = _services[i - 1];
         const auto* name = service->GetName();
         success = service->Stop();
-        if (success)
-        {
-            Log::Info(name, " stopped successfully.");
-        }
-        else
-        {
-            Log::Info(name, " failed to stop. This service might have been stopped earlier.");
-        }
+        LogServiceStop(success, name);
         result &= success;
     }
 
@@ -1513,7 +1537,16 @@ HRESULT STDMETHODCALLTYPE CorProfilerCallback::Shutdown()
 #ifdef LINUX
     if (_pCpuProfiler != nullptr)
     {
-        _pCpuProfiler->Stop();
+        // if we failed at stopping the time_create-based CPU profiler,
+        // it's safer to not release the memory.
+        // Otherwise, we might crash the application.
+        // Reason: one thread could be executing the signal handler and accessing some field
+        auto stopped = _pCpuProfiler->Stop();
+        LogServiceStop(stopped, _pCpuProfiler->GetName());
+        if (stopped)
+        {
+            _pCpuProfiler = nullptr;
+        }
     }
 #endif
 
@@ -1776,7 +1809,7 @@ void CorProfilerCallback::OnThreadRoutineFinished()
         return;
     }
 
-    auto* cpuProfiler = myThis->_pCpuProfiler;
+    auto* cpuProfiler = myThis->_pCpuProfiler.get();
     if (cpuProfiler == nullptr)
     {
         return;

profiler/src/ProfilerEngine/Datadog.Profiler.Native/CorProfilerCallback.h

@@ -34,8 +34,11 @@
 #include "ProxyMetric.h"
 #include "IAllocationsRecorder.h"
 #include "IMetadataProvider.h"
-#include "ThreadLifetimeProvider.h"
 #include "shared/src/native-src/string.h"
+#include "ThreadLifetimeProvider.h"
+#ifdef LINUX
+#include "TimerCreateCpuProfiler.h"
+#endif
 #include "IEtwEventsManager.h"
 #include "ISsiLifetime.h"
 
@@ -54,7 +57,6 @@ class IConfiguration;
 class IExporter;
 class RawSampleTransformer;
 class RuntimeIdStore;
-class TimerCreateCpuProfiler;
 class CpuSampleProvider;
 class NetworkProvider;
 
@@ -254,7 +256,7 @@ private :
     RuntimeIdStore* _pRuntimeIdStore = nullptr;
 #ifdef LINUX
     SystemCallsShield* _systemCallsShield = nullptr;
-    TimerCreateCpuProfiler* _pCpuProfiler = nullptr;
+    std::unique_ptr<TimerCreateCpuProfiler> _pCpuProfiler = nullptr;
     CpuSampleProvider* _pCpuSampleProvider = nullptr;
 #endif
 

profiler/test/Datadog.Profiler.IntegrationTests/LinuxOnly/SignalHandlerTest.cs

@@ -47,10 +47,14 @@ public void CheckSignalHandlerIsInstalledOnce(string appName, string framework,
             var logFile = Directory.GetFiles(runner.Environment.LogDir)
                 .Single(f => Path.GetFileName(f).StartsWith("DD-DotNet-Profiler-Native-"));
 
-            var nbSignalHandlerInstallation = File.ReadLines(logFile)
-                .Count(l => l.Contains("Successfully setup signal handler for"));
-
-            nbSignalHandlerInstallation.Should().Be(1);
+            
+            File.ReadLines(logFile)
+                .Count(l => l.Contains("Successfully setup signal handler for User defined signal 1 signal"))
+                .Should().Be(1);
+
+            File.ReadLines(logFile)
+                .Count(l => l.Contains("Successfully setup signal handler for Profiling timer expired signal"))
+                .Should().Be(1);
         }
     }
 }