[Profiler] Improve CodeHotspots (#3501)

* Fix sleep API we use to avoid non-precise wakeup time
* Add new list of managed thread: the ones that already have a trace context attached.

profiler/src/Demos/Samples.BuggyBits/Program.cs

@@ -34,7 +34,7 @@ public static async Task Main(string[] args)
 
             EnvironmentInfo.PrintDescriptionToConsole();
 
-            ParseCommandLine(args, out var timeout, out var iterations, out var scenario);
+            ParseCommandLine(args, out var timeout, out var iterations, out var scenario, out var nbIdleThreads);
 
             using (var host = CreateHostBuilder(args).Build())
             {
@@ -53,7 +53,7 @@ public static async Task Main(string[] args)
                 WriteLine($"Listening to {rootUrl}");
 
                 var cts = new CancellationTokenSource();
-                using (var selfInvoker = new SelfInvoker(cts.Token, scenario))
+                using (var selfInvoker = new SelfInvoker(cts.Token, scenario, nbIdleThreads))
                 {
                     await host.StartAsync();
 
@@ -121,12 +121,13 @@ public static IHostBuilder CreateHostBuilder(string[] args) =>
                     webBuilder.UseStartup<Startup>();
                 });
 
-        private static void ParseCommandLine(string[] args, out TimeSpan timeout, out int iterations, out Scenario scenario)
+        private static void ParseCommandLine(string[] args, out TimeSpan timeout, out int iterations, out Scenario scenario, out int nbIdleThreads)
         {
             // by default, need interactive action to exit and string.Concat scenario
             timeout = TimeSpan.MinValue;
             iterations = 0;
             scenario = Scenario.StringConcat;
+            nbIdleThreads = 0;
 
             for (int i = 0; i < args.Length; i++)
             {
@@ -171,6 +172,15 @@ private static void ParseCommandLine(string[] args, out TimeSpan timeout, out in
                 {
                     timeout = Timeout.InfiniteTimeSpan;
                 }
+                else
+                if ("--with-idle-threads".Equals(arg, StringComparison.OrdinalIgnoreCase))
+                {
+                    var nbThreadsArgument = i + 1;
+                    if (nbThreadsArgument >= args.Length || !int.TryParse(args[nbThreadsArgument], out nbIdleThreads))
+                    {
+                        throw new InvalidOperationException($"Invalid or missing count after --with-idle-threads");
+                    }
+                }
             }
 
             // sanity checks

profiler/src/Demos/Samples.BuggyBits/SelfInvoker.cs

@@ -18,12 +18,14 @@ public class SelfInvoker : IDisposable
         private readonly CancellationToken _exitToken;
         private readonly HttpClient _httpClient;
         private readonly Scenario _scenario;
+        private readonly int _nbIdleThreads;
 
-        public SelfInvoker(CancellationToken token, Scenario scenario)
+        public SelfInvoker(CancellationToken token, Scenario scenario, int nbIdleThreds)
         {
             _exitToken = token;
             _httpClient = new HttpClient();
             _scenario = scenario;
+            _nbIdleThreads = nbIdleThreds;
         }
 
         public void Dispose()
@@ -35,6 +37,8 @@ public async Task RunAsync(string rootUrl, int iterations = 0)
         {
             Console.WriteLine($"{this.GetType().Name} started.");
 
+            CreateIdleThreads();
+
             if (_scenario == Scenario.None)
             {
                 await Task.Delay(Timeout.Infinite, _exitToken);
@@ -67,6 +71,16 @@ public async Task RunAsync(string rootUrl, int iterations = 0)
             Console.WriteLine($"{this.GetType().Name} stopped.");
         }
 
+        private void CreateIdleThreads()
+        {
+            Console.WriteLine($"----- Creating {_nbIdleThreads} idle threads");
+
+            for (var i = 0; i < _nbIdleThreads; i++)
+            {
+                Task.Factory.StartNew(() => { _exitToken.WaitHandle.WaitOne(); }, TaskCreationOptions.LongRunning);
+            }
+        }
+
         private string GetEndpoint(string rootUrl)
         {
             switch (_scenario)

profiler/src/ProfilerEngine/Datadog.Profiler.Native.Windows/Windows32BitStackFramesCollector.cpp

@@ -30,7 +30,6 @@ StackSnapshotResultBuffer* Windows32BitStackFramesCollector::CollectStackSampleI
 {
     // Collect data for TraceContext Tracking:
     bool traceContextDataCollected = this->TryApplyTraceContextDataFromCurrentCollectionThreadToSnapshot();
-    assert(traceContextDataCollected);
 
     // Now walk the stack:
     __try

profiler/src/ProfilerEngine/Datadog.Profiler.Native.Windows/Windows64BitStackFramesCollector.cpp

@@ -181,7 +181,6 @@ StackSnapshotResultBuffer* Windows64BitStackFramesCollector::CollectStackSampleI
 {
     // Collect data for TraceContext Tracking:
     bool traceContextDataCollected = this->TryApplyTraceContextDataFromCurrentCollectionThreadToSnapshot();
-    assert(traceContextDataCollected);
 
     // Now walk the stack:
     CONTEXT context;

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

@@ -59,6 +59,7 @@ Configuration::Configuration()
     _cpuWallTimeSamplingRate = ExtractCpuWallTimeSamplingRate();
     _walltimeThreadsThreshold = ExtractWallTimeThreadsThreshold();
     _cpuThreadsThreshold = ExtractCpuThreadsThreshold();
+    _codeHotspotsThreadsThreshold = ExtractCodeHotspotsThreadsThreshold();
     _minimumCores = GetEnvironmentValue<double>(EnvironmentVariables::CoreMinimumOverride, 1.0);
     _namedPipeName = GetEnvironmentValue(EnvironmentVariables::NamedPipeName, DefaultEmptyString);
     _isTimestampsAsLabelEnabled = GetEnvironmentValue(EnvironmentVariables::TimestampsAsLabelEnabled, false);
@@ -167,6 +168,11 @@ int32_t Configuration::CpuThreadsThreshold() const
     return _cpuThreadsThreshold;
 }
 
+int32_t Configuration::CodeHotspotsThreadsThreshold() const
+{
+    return _codeHotspotsThreadsThreshold;
+}
+
 double Configuration::MinimumCores() const
 {
     return _minimumCores;
@@ -366,6 +372,13 @@ int32_t Configuration::ExtractWallTimeThreadsThreshold()
     return threshold;
 }
 
+int32_t Configuration::ExtractCodeHotspotsThreadsThreshold()
+{
+    // default threads to sample for codehotspots is 10; could be changed via env vars but down to 1ms
+    int32_t threshold = std::max(GetEnvironmentValue(EnvironmentVariables::CodeHotspotsThreadsThreshold, 10), 1);
+    return threshold;
+}
+
 int32_t Configuration::ExtractCpuThreadsThreshold()
 {
     // default threads to sample for CPU profiling is 64; could be changed via env vars from 5 to 128

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

@@ -52,6 +52,7 @@ class Configuration final : public IConfiguration
     bool IsTimestampsAsLabelEnabled() const override;
     int32_t WalltimeThreadsThreshold() const override;
     int32_t CpuThreadsThreshold() const override;
+    int32_t CodeHotspotsThreadsThreshold() const override;
     bool IsGarbageCollectionProfilingEnabled() const override;
 
 private:
@@ -72,6 +73,7 @@ class Configuration final : public IConfiguration
     static std::chrono::nanoseconds ExtractCpuWallTimeSamplingRate();
     static int32_t ExtractWallTimeThreadsThreshold();
     static int32_t ExtractCpuThreadsThreshold();
+    static int32_t ExtractCodeHotspotsThreadsThreshold();
     static bool GetContention();
 
 private:
@@ -116,6 +118,7 @@ class Configuration final : public IConfiguration
     std::chrono::nanoseconds _cpuWallTimeSamplingRate;
     int32_t _walltimeThreadsThreshold;
     int32_t _cpuThreadsThreshold;
+    int32_t _codeHotspotsThreadsThreshold;
 
     double _minimumCores;
     std::string _namedPipeName;

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

@@ -114,6 +114,8 @@ bool CorProfilerCallback::InitializeServices()
 
     _pManagedThreadList = RegisterService<ManagedThreadList>(_pCorProfilerInfo);
 
+    _pCodeHotspotsThreadList = RegisterService<ManagedThreadList>(_pCorProfilerInfo);
+
     auto* pRuntimeIdStore = RegisterService<RuntimeIdStore>();
 
     // Each sample contains a vector of values.
@@ -245,6 +247,7 @@ bool CorProfilerCallback::InitializeServices()
         _pClrLifetime.get(),
         _pThreadsCpuManager,
         _pManagedThreadList,
+        _pCodeHotspotsThreadList,
         _pWallTimeProvider,
         _pCpuTimeProvider);
 
@@ -342,6 +345,7 @@ bool CorProfilerCallback::DisposeServices()
     _pThreadsCpuManager = nullptr;
     _pStackSamplerLoopManager = nullptr;
     _pManagedThreadList = nullptr;
+    _pCodeHotspotsThreadList = nullptr;
     _pApplicationStore = nullptr;
 
     return result;
@@ -1104,13 +1108,18 @@ HRESULT STDMETHODCALLTYPE CorProfilerCallback::ThreadDestroyed(ThreadID threadId
     }
 
     std::shared_ptr<ManagedThreadInfo> pThreadInfo;
-    if (_pManagedThreadList->UnregisterThread(threadId, pThreadInfo))
+    Log::Debug("Removing thread ", std::hex, threadId, " from the trace context threads list.");
+    if (_pCodeHotspotsThreadList->UnregisterThread(threadId, pThreadInfo))
     {
         // The docs require that we do not allow to destroy a thread while it is being stack-walked.
         // TO ensure this, SetThreadDestroyed(..) acquires the StackWalkLock associated with this ThreadInfo.
         pThreadInfo->SetThreadDestroyed();
+        pThreadInfo.reset();
     }
 
+    Log::Debug("Removing thread ", std::hex, threadId, " from the main managed thread list.");
+    _pManagedThreadList->UnregisterThread(threadId, pThreadInfo);
+
     return S_OK;
 }
 

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

@@ -182,6 +182,7 @@ class CorProfilerCallback : public ICorProfilerCallback10
 public:
     IThreadsCpuManager* GetThreadsCpuManager() { return _pThreadsCpuManager; }
     IManagedThreadList* GetManagedThreadList() { return _pManagedThreadList; }
+    IManagedThreadList* GetCodeHotspotThreadList() { return _pCodeHotspotsThreadList; }
     IStackSamplerLoopManager* GetStackSamplerLoopManager() { return _pStackSamplerLoopManager; }
     IApplicationStore* GetApplicationStore() { return _pApplicationStore; }
     IExporter* GetExporter() { return _pExporter.get(); }
@@ -204,6 +205,7 @@ private :
     IThreadsCpuManager* _pThreadsCpuManager = nullptr;
     IStackSamplerLoopManager* _pStackSamplerLoopManager = nullptr;
     IManagedThreadList* _pManagedThreadList = nullptr;
+    IManagedThreadList* _pCodeHotspotsThreadList = nullptr;
     IApplicationStore* _pApplicationStore = nullptr;
     ExceptionsProvider* _pExceptionsProvider = nullptr;
     WallTimeProvider* _pWallTimeProvider = nullptr;

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

@@ -43,6 +43,7 @@ class EnvironmentVariables final
     inline static const shared::WSTRING CpuWallTimeSamplingRate     = WStr("DD_INTERNAL_PROFILING_SAMPLING_RATE");
     inline static const shared::WSTRING WalltimeThreadsThreshold    = WStr("DD_INTERNAL_PROFILING_WALLTIME_THREADS_THRESHOLD");
     inline static const shared::WSTRING CpuTimeThreadsThreshold     = WStr("DD_INTERNAL_PROFILING_CPUTIME_THREADS_THRESHOLD");
+    inline static const shared::WSTRING CodeHotspotsThreadsThreshold = WStr("DD_INTERNAL_PROFILING_CODEHOTSPOTS_THREADS_THRESHOLD");
     inline static const shared::WSTRING TimestampsAsLabelEnabled    = WStr("DD_INTERNAL_PROFILING_TIMESTAMPS_AS_LABEL_ENABLED");
     inline static const shared::WSTRING ProfilesOutputDir           = WStr("DD_INTERNAL_PROFILING_OUTPUT_DIR");
     inline static const shared::WSTRING DevelopmentConfiguration    = WStr("DD_INTERNAL_USE_DEVELOPMENT_CONFIGURATION");

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

@@ -49,5 +49,6 @@ class IConfiguration
     virtual bool IsTimestampsAsLabelEnabled() const = 0;
     virtual int32_t WalltimeThreadsThreshold() const = 0;
     virtual int32_t CpuThreadsThreshold() const = 0;
+    virtual int32_t CodeHotspotsThreadsThreshold() const = 0;
     virtual bool IsGarbageCollectionProfilingEnabled() const = 0;
 };

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

@@ -14,6 +14,7 @@ class IManagedThreadList : public IService
 {
 public:
     virtual bool GetOrCreateThread(ThreadID clrThreadId) = 0;
+    virtual bool RegisterThread(std::shared_ptr<ManagedThreadInfo>& pThreadInfo) = 0;
     virtual bool UnregisterThread(ThreadID clrThreadId, std::shared_ptr<ManagedThreadInfo>& ppThreadInfo) = 0;
     virtual bool SetThreadOsInfo(ThreadID clrThreadId, DWORD osThreadId, HANDLE osThreadHandle) = 0;
     virtual bool SetThreadName(ThreadID clrThreadId, const shared::WSTRING& threadName) = 0;

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

@@ -77,6 +77,7 @@ struct ManagedThreadInfo
     inline std::uint64_t GetLocalRootSpanId() const;
     inline std::uint64_t GetSpanId() const;
     inline bool CanReadTraceContext() const;
+    inline bool HasTraceContext() const;
 
     inline std::string GetProfileThreadId();
     inline std::string GetProfileThreadName();
@@ -358,3 +359,15 @@ inline bool ManagedThreadInfo::CanReadTraceContext() const
     std::atomic_thread_fence(std::memory_order_acquire);
     return canReadTraceContext == 0;
 }
+
+inline bool ManagedThreadInfo::HasTraceContext() const
+{
+    if (CanReadTraceContext())
+    {
+        std::uint64_t localRootSpanId = GetLocalRootSpanId();
+        std::uint64_t spanId = GetSpanId();
+
+        return localRootSpanId != 0 && spanId != 0;
+    }
+    return false;
+}

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

@@ -131,7 +131,7 @@ bool ManagedThreadList::UnregisterThread(ThreadID clrThreadId, std::shared_ptr<M
     uint32_t pos = 0;
     for (auto i = _threads.begin(); i != _threads.end(); ++i)
     {
-        auto pInfo = *i;
+        std::shared_ptr<ManagedThreadInfo> pInfo = *i; // make a copy so it can be moved later
         if (pInfo->GetClrThreadId() == clrThreadId)
         {
 
@@ -151,7 +151,7 @@ bool ManagedThreadList::UnregisterThread(ThreadID clrThreadId, std::shared_ptr<M
         pos++;
     }
 
-    Log::Error("ManagedThreadList: thread ", std::dec, clrThreadId, "cannot be unregister because not in the list");
+    Log::Debug("ManagedThreadList: thread ", std::dec, clrThreadId, " cannot be unregister because not in the list");
     return false;
 }
 
@@ -372,4 +372,23 @@ std::shared_ptr<ManagedThreadInfo> ManagedThreadList::FindByClrId(ThreadID clrTh
     {
         return elem->second;
     }
+}
+
+bool ManagedThreadList::RegisterThread(std::shared_ptr<ManagedThreadInfo>& pThreadInfo)
+{
+    std::lock_guard<std::recursive_mutex> lock(_mutex);
+
+    auto it = _lookupByClrThreadId.find(pThreadInfo->GetClrThreadId());
+    if (it == _lookupByClrThreadId.cend())
+    {
+        // not registered yet
+
+        _threads.push_back(pThreadInfo);
+        _lookupByClrThreadId[pThreadInfo->GetClrThreadId()] = pThreadInfo;
+        _lookupByProfilerThreadInfoId[pThreadInfo->GetProfilerThreadInfoId()] = pThreadInfo;
+
+        return true;
+    }
+
+    return false;
 }

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

@@ -31,6 +31,7 @@ class ManagedThreadList : public IManagedThreadList
     bool Start() override;
     bool Stop() override;
     bool GetOrCreateThread(ThreadID clrThreadId) override;
+    bool RegisterThread(std::shared_ptr<ManagedThreadInfo>& pThreadInfo) override;
     bool UnregisterThread(ThreadID clrThreadId, std::shared_ptr<ManagedThreadInfo>& ppThreadInfo) override;
     bool SetThreadOsInfo(ThreadID clrThreadId, DWORD osThreadId, HANDLE osThreadHandle) override;
     bool SetThreadName(ThreadID clrThreadId, const shared::WSTRING& threadName) override;

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

@@ -383,4 +383,13 @@ bool OpSysTools::IsSafeToStartProfiler(double coresThreshold)
     return true;
 
 #endif
-}
+}
+
+void OpSysTools::Sleep(std::chrono::nanoseconds duration)
+{
+#ifdef _WINDOWS
+    ::Sleep(static_cast<DWORD>(duration.count() / 1000000));
+#else
+    usleep(duration.count() / 1000);
+#endif
+}

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

@@ -72,6 +72,8 @@ class OpSysTools final
     static bool IsSafeToStartProfiler(double coresThreshold);
     static std::int64_t GetHighPrecisionTimestamp();
 
+    static void Sleep(std::chrono::nanoseconds duration);
+
 private:
     static constexpr std::int64_t NanosecondsPerSecond = 1000000000;
 

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

@@ -71,6 +71,8 @@ extern "C" void* __stdcall GetPointerToNativeTraceContext()
         return nullptr;
     }
 
+    profiler->GetCodeHotspotThreadList()->RegisterThread(pCurrentThreadInfo);
+
     // Get pointers to the relevant fields within the thread info data structure.
     return pCurrentThreadInfo->GetTraceContextPointer();
 }