[Profiler] Implement WaitHandle wait duration profiling

Datadog.Profiler.sln

@@ -111,6 +111,8 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "dd-prof-etw-replay", "profi
 EndProject
 Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "dd-prof-etw-agent", "profiler\src\Tools\ETW\dd-prof-etw\dd-prof-etw-agent\dd-prof-etw-agent.csproj", "{B9662E54-7FE8-4199-B98F-3125E0D9F225}"
 EndProject
+Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Samples.WaitHandles", "profiler\src\Demos\Samples.WaitHandles\Samples.WaitHandles.csproj", "{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF}"
+EndProject
 Global
 	GlobalSection(SolutionConfigurationPlatforms) = preSolution
 		Debug|Any CPU = Debug|Any CPU
@@ -485,6 +487,22 @@ Global
 		{B9662E54-7FE8-4199-B98F-3125E0D9F225}.Release|x64.Build.0 = Release|Any CPU
 		{B9662E54-7FE8-4199-B98F-3125E0D9F225}.Release|x86.ActiveCfg = Release|Any CPU
 		{B9662E54-7FE8-4199-B98F-3125E0D9F225}.Release|x86.Build.0 = Release|Any CPU
+		{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
+		{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF}.Debug|Any CPU.Build.0 = Debug|Any CPU
+		{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF}.Debug|ARM64.ActiveCfg = Debug|Any CPU
+		{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF}.Debug|ARM64.Build.0 = Debug|Any CPU
+		{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF}.Debug|x64.ActiveCfg = Debug|x64
+		{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF}.Debug|x64.Build.0 = Debug|x64
+		{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF}.Debug|x86.ActiveCfg = Debug|x86
+		{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF}.Debug|x86.Build.0 = Debug|x86
+		{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF}.Release|Any CPU.ActiveCfg = Release|Any CPU
+		{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF}.Release|Any CPU.Build.0 = Release|Any CPU
+		{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF}.Release|ARM64.ActiveCfg = Release|Any CPU
+		{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF}.Release|ARM64.Build.0 = Release|Any CPU
+		{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF}.Release|x64.ActiveCfg = Release|x64
+		{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF}.Release|x64.Build.0 = Release|x64
+		{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF}.Release|x86.ActiveCfg = Release|x86
+		{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF}.Release|x86.Build.0 = Release|x86
 	EndGlobalSection
 	GlobalSection(SolutionProperties) = preSolution
 		HideSolutionNode = FALSE
@@ -525,6 +543,7 @@ Global
 		{EACEAEE9-23A6-448F-A56E-39FE4E837FA6} = {3437D742-5FB6-4457-8291-1EBBADBEE1BC}
 		{837CD3F8-08E9-4952-9834-5179B60242DD} = {C1D06C89-E4D1-4E09-9AB6-35BB5A1DEB04}
 		{B9662E54-7FE8-4199-B98F-3125E0D9F225} = {C1D06C89-E4D1-4E09-9AB6-35BB5A1DEB04}
+		{44E45EBD-D52C-4BDA-A52C-E340AF1D5AAF} = {D2476213-2D12-43A8-966C-BCFCE098FD63}
 	EndGlobalSection
 	GlobalSection(ExtensibilityGlobals) = postSolution
 		SolutionGuid = {917C242A-028D-42FD-BA47-E7317B6A36B4}

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

@@ -0,0 +1,119 @@
+// <copyright file="Program.cs" company="Datadog">
+// Unless explicitly stated otherwise all files in this repository are licensed under the Apache 2 License.
+// This product includes software developed at Datadog (https://www.datadoghq.com/). Copyright 2022 Datadog, Inc.
+// </copyright>
+
+using System;
+using System.Diagnostics;
+using System.Runtime.InteropServices;
+using System.Threading;
+
+namespace Samples.WaitHandles
+{
+    public class Program
+    {
+        static AutoResetEvent autoResetEvent = new AutoResetEvent(false);
+        static ManualResetEvent manualResetEvent = new ManualResetEvent(false);
+        static Mutex mutex = new Mutex();
+        static Semaphore semaphore = new Semaphore(1, 1);
+
+        public static void Main()
+        {
+            Console.WriteLine($"pid = {Process.GetCurrentProcess().Id}");
+            Console.WriteLine("Press Enter to start the threads...");
+            //Console.ReadLine();
+
+            // Create and start threads for different synchronization scenarios
+            Console.WriteLine();
+            Console.WriteLine("Starting threads...");
+
+            Stopwatch sw = new Stopwatch();
+            for (int i = 0; i < 5; i++)
+            {
+                sw.Restart();
+
+                // start a thread that will own the mutex and the semaphore
+                var owningThread = new Thread(OwningThread);
+                owningThread.Start();
+                Thread.Sleep(5);
+
+                var autoResetEventThread = new Thread(AutoResetEventThread);
+                autoResetEventThread.Start();
+
+                var manualResetEventThread = new Thread(ManualResetEventThread);
+                manualResetEventThread.Start();
+
+                var mutexThread = new Thread(MutexThread);
+                mutexThread.Start();
+
+                var semaphoreThread = new Thread(SemaphoreThread);
+                semaphoreThread.Start();
+
+                // wait for all threads to finish
+                owningThread.Join();
+                autoResetEventThread.Join();
+                manualResetEventThread.Join();
+                mutexThread.Join();
+                semaphoreThread.Join();
+
+                sw.Stop();
+                Console.WriteLine("___________________________________________");
+                Console.WriteLine($"Duration = {sw.ElapsedMilliseconds} ms");
+
+                Thread.Sleep(2);
+            }
+        }
+
+        private static void OwningThread()
+        {
+            Console.WriteLine();
+            Console.WriteLine($"    [{GetCurrentThreadId(),8}] Start to hold resources");
+            Console.WriteLine("___________________________________________");
+            mutex.WaitOne();
+            semaphore.WaitOne();
+
+            Thread.Sleep(3000);
+            Console.WriteLine();
+            Console.WriteLine("    Release resources");
+
+            mutex.ReleaseMutex();
+            semaphore.Release(1);
+            autoResetEvent.Set();
+            manualResetEvent.Set();
+        }
+
+        private static void AutoResetEventThread()
+        {
+            Console.WriteLine($"    [{GetCurrentThreadId(),8}] waiting for AutoResetEvent...");
+            autoResetEvent.WaitOne();
+            Console.WriteLine("    <-- AutoResetEvent");
+        }
+
+        private static void ManualResetEventThread()
+        {
+            Console.WriteLine($"    [{GetCurrentThreadId(),8}] waiting for ManualResetEvent...");
+            manualResetEvent.WaitOne();
+            manualResetEvent.Reset();
+            Console.WriteLine("    <-- ManualResetEvent");
+        }
+
+        private static void MutexThread()
+        {
+            Console.WriteLine($"    [{GetCurrentThreadId(),8}] waiting for Mutex...");
+            mutex.WaitOne();
+            mutex.ReleaseMutex();
+            Console.WriteLine("    <-- Mutex");
+        }
+
+        private static void SemaphoreThread()
+        {
+            Console.WriteLine($"    [{GetCurrentThreadId(),8}] waiting for Semaphore");
+            semaphore.WaitOne();
+            semaphore.Release(1);
+            Console.WriteLine("    <-- Semaphore");
+        }
+
+        [DllImport("kernel32.dll")]
+        private static extern uint GetCurrentThreadId();
+    }
+}

profiler/src/Demos/Samples.WaitHandles/Properties/launchSettings.json

@@ -0,0 +1,43 @@
+{
+  "profiles": {
+    "Samples.WaitHandles": {
+      "commandName": "Project",
+      "commandLineArgs": "10",
+      "environmentVariables": {
+        "COR_ENABLE_PROFILING": "1",
+        "COR_PROFILER": "{BD1A650D-AC5D-4896-B64F-D6FA25D6B26A}",
+        "COR_PROFILER_PATH_64": "$(BuildOutputRoot)\\bin\\$(Configuration)-x64\\profiler\\src\\ProfilerEngine\\Datadog.Profiler.Native.Windows\\Datadog.Profiler.Native.dll",
+        "COR_PROFILER_PATH_32": "$(BuildOutputRoot)\\bin\\$(Configuration)-x86\\profiler\\src\\ProfilerEngine\\Datadog.Profiler.Native.Windows\\Datadog.Profiler.Native.dll",
+
+        "CORECLR_ENABLE_PROFILING": "1",
+        "CORECLR_PROFILER": "{BD1A650D-AC5D-4896-B64F-D6FA25D6B26A}",
+        "CORECLR_PROFILER_PATH_64": "$(BuildOutputRoot)\\bin\\$(Configuration)-x64\\profiler\\src\\ProfilerEngine\\Datadog.Profiler.Native.Windows\\Datadog.Profiler.Native.dll",
+        "CORECLR_PROFILER_PATH_32": "$(BuildOutputRoot)\\bin\\$(Configuration)-x86\\profiler\\src\\ProfilerEngine\\Datadog.Profiler.Native.Windows\\Datadog.Profiler.Native.dll",
+
+        "COMPlus_EnableDiagnostics": "1",
+
+        "DD_PROFILING_ENABLED": "1",
+        "DD_PROFILING_WALLTIME_ENABLED": "0",
+        "DD_PROFILING_CPU_ENABLED": "0",
+        "DD_PROFILING_EXCEPTION_ENABLED": "0",
+        "DD_PROFILING_LOCK_ENABLED": "0",
+        "DD_PROFILING_ALLOCATION_ENABLED": "0",
+        "DD_PROFILING_HEAP_ENABLED": "0",
+        "DD_PROFILING_GC_ENABLED": "0",
+        "DD_INTERNAL_PROFILING_ALLOCATION_RECORDER_ENABLED": "0",
+        "DD_INTERNAL_PROFILING_HTTP_ENABLED": "0",
+        "DD_INTERNAL_PROFILING_FORCE_HTTP_SAMPLING": "0",
+        "DD_INTERNAL_PROFILING_WAITHANDLE_ENABLED": "1",
+
+        "DD_INTERNAL_PROFILING_TIMESTAMPS_AS_LABEL_ENABLED": "1",
+        "DD_INTERNAL_PROFILING_OUTPUT_DIR": "$(PROGRAMDATA)\\Datadog-APM\\Pprof-files\\DotNet",
+        "DD_TRACE_DEBUG": "1",
+        "DD_ENV": "apm-profiling-local",
+        "DD_SERVICE": "dd-dotnet-waithandle",
+        "DD_INTERNAL_PROFILING_DEBUG_INFO_ENABLED": "0",
+        "DD_INTERNAL_USE_DEVELOPMENT_CONFIGURATION": "false"
+      },
+      "nativeDebugging": true
+    }
+  }
+}

profiler/src/Demos/Samples.WaitHandles/Samples.WaitHandles.csproj

@@ -0,0 +1,6 @@
+<Project Sdk="Microsoft.NET.Sdk">
+  <PropertyGroup>
+    <OutputType>Exe</OutputType>
+    <TargetFramework>net9.0</TargetFramework>
+  </PropertyGroup>
+</Project>

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

@@ -76,8 +76,13 @@ void ClrEventsParser::ParseEvent(
     {
         ParseContentionEvent(id, version, cbEventData, eventData);
     }
+    else if (KEYWORD_WAITHANDLE == (keywords & KEYWORD_WAITHANDLE))
+    {
+        ParseWaitHandleEvent(timestamp, id, version, cbEventData, eventData);
+    }
 }
 
+
 // TL;DR Deactivate the alignment check in the Undefined Behavior Sanitizers for the ParseGcEvent function
 // because events fields are not aligned in the bitstream sent by the CLR.
 //
@@ -303,6 +308,48 @@ void ClrEventsParser::ParseContentionEvent(DWORD id, DWORD version, ULONG cbEven
     }
 }
 
+void ClrEventsParser::ParseWaitHandleEvent(std::chrono::nanoseconds timestamp, DWORD id, DWORD version, ULONG cbEventData, LPCBYTE pEventData)
+{
+    if (_pContentionListener == nullptr)
+    {
+        return;
+    }
+
+    if (id == EVENT_WAITHANDLE_START)
+    {
+        // <template tid="WaitHandleWaitStart">
+        //     <data name="WaitSource" inType="win:UInt8" map="WaitHandleWaitSourceMap" />
+        //     <data name="AssociatedObjectID" inType="win:Pointer" />
+        //     data name="ClrInstanceID" inType="win:UInt16" />
+        // </template>
+
+        WaitHandleWaitStartPayload payload{0};
+        ULONG offset = 0;
+        if (!Read<WaitHandleWaitStartPayload>(payload, pEventData, cbEventData, offset))
+        {
+            return;
+        }
+
+        _pContentionListener->OnWaitStart(timestamp, payload.AssociatedObjectID);
+    }
+    else
+    if (id == EVENT_WAITHANDLE_STOP)
+    {
+        // <template tid="WaitHandleWaitStart">
+        //     data name="ClrInstanceID" inType="win:UInt16" />
+        // </template>
+
+        WaitHandleWaitStopPayload payload{0};
+        ULONG offset = 0;
+        if (!Read<WaitHandleWaitStopPayload>(payload, pEventData, cbEventData, offset))
+        {
+            return;
+        }
+
+        _pContentionListener->OnWaitStop(timestamp);
+    }
+}
+
 void ClrEventsParser::NotifySuspension(std::chrono::nanoseconds timestamp, uint32_t number, uint32_t generation, std::chrono::nanoseconds duration)
 {
     if (_pGCSuspensionsListener != nullptr)

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

@@ -25,9 +25,9 @@
 
 
 // keywords
-const int KEYWORD_CONTENTION = 0x00004000;
-const int KEYWORD_GC = 0x00000001;
-const int KEYWORD_STACKWALK = 0x40000000;
+const int64_t KEYWORD_CONTENTION = 0x00004000;
+const int64_t KEYWORD_GC = 0x00000001;
+const int64_t KEYWORD_STACKWALK = 0x40000000;
 
 // events id
 const int EVENT_CONTENTION_STOP = 91; // version 1 contains the duration in nanoseconds
@@ -204,6 +204,18 @@ struct GCGlobalHeapPayload
     uint32_t Reason;
     uint32_t GlobalMechanisms;
 };
+
+struct WaitHandleWaitStartPayload // for .NET 9+
+{
+    uint8_t WaitSource;   // 0 if AssociatedObjectID is null or 1 otherwise
+    uintptr_t AssociatedObjectID; // null or the address of the WaitHandle-derived object
+    uint16_t ClrInstanceId;    // Unique ID for the instance of CLR.
+};
+
+struct WaitHandleWaitStopPayload // for .NET 9+
+{
+    uint16_t ClrInstanceId;    // Unique ID for the instance of CLR.
+};
 #pragma pack()
 
 class IContentionListener;
@@ -232,8 +244,9 @@ struct GCDetails
 class ClrEventsParser
 {
 public:
-    static const int KEYWORD_GC = 0x1;
-    static const int KEYWORD_CONTENTION = 0x4000;
+    static const int64_t KEYWORD_GC = 0x1;
+    static const int64_t KEYWORD_CONTENTION = 0x4000;
+    static const int64_t KEYWORD_WAITHANDLE = 0x40000000000; // .NET 9+ only
 
 public:
     ClrEventsParser(
@@ -264,6 +277,7 @@ class ClrEventsParser
 private:
     void ParseGcEvent(std::chrono::nanoseconds timestamp, DWORD id, DWORD version, ULONG cbEventData, LPCBYTE pEventData);
     void ParseContentionEvent(DWORD id, DWORD version, ULONG cbEventData, LPCBYTE pEventData);
+    void ParseWaitHandleEvent(std::chrono::nanoseconds timestamp, DWORD id, DWORD version, ULONG cbEventData, LPCBYTE pEventData);
 
     // garbage collection events processing
     void OnGCTriggered();
@@ -342,8 +356,10 @@ class ClrEventsParser
 
 private:
     const int EVENT_ALLOCATION_TICK = 10;   // version 4 contains the size + reference
-    const int EVENT_CONTENTION_STOP = 91;   // version 1 contains the duration in nanoseconds
     const int EVENT_CONTENTION_START = 81; // version 2 contains thread id of the threads that owns the lock
+    const int EVENT_CONTENTION_STOP = 91;   // version 1 contains the duration in nanoseconds
+    const int EVENT_WAITHANDLE_START = 301;
+    const int EVENT_WAITHANDLE_STOP = 302;
 
     // Events emitted during garbage collection lifetime
     // read https://medium.com/criteo-engineering/spying-on-net-garbage-collector-with-net-core-eventpipes-9f2a986d5705?source=friends_link&sk=baf9a7766fb5c7899b781f016803597f

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

@@ -250,8 +250,10 @@ class CollectorBase
         }
     }
 
-private:
+protected:
     IFrameStore* _pFrameStore = nullptr;
+
+private:
     IAppDomainStore* _pAppDomainStore = nullptr;
     IRuntimeIdStore* _pRuntimeIdStore = nullptr;
     IThreadsCpuManager* _pThreadsCpuManager = nullptr;

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

@@ -99,6 +99,7 @@ Configuration::Configuration()
     _isTelemetryToDiskEnabled = GetEnvironmentValue(EnvironmentVariables::TelemetryToDiskEnabled, false);
     _isSsiTelemetryEnabled = GetEnvironmentValue(EnvironmentVariables::SsiTelemetryEnabled, false);
     _cpuProfilerType = GetEnvironmentValue(EnvironmentVariables::CpuProfilerType, CpuProfilerType::ManualCpuTime);
+    _isWaitHandleProfilingEnabled = GetEnvironmentValue(EnvironmentVariables::WaitHandleProfilingEnabled, false);
 }
 
 fs::path Configuration::ExtractLogDirectory()
@@ -746,3 +747,8 @@ bool Configuration::IsSsiTelemetryEnabled() const
 {
     return _isSsiTelemetryEnabled;
 }
+
+bool Configuration::IsWaitHandleProfilingEnabled() const
+{
+    return _isWaitHandleProfilingEnabled;
+}

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

@@ -81,6 +81,7 @@ class Configuration final : public IConfiguration
     bool IsSsiTelemetryEnabled() const override;
     CpuProfilerType GetCpuProfilerType() const override;
     std::chrono::milliseconds GetCpuProfilingInterval() const override;
+    bool IsWaitHandleProfilingEnabled() const override;
 
 private:
     static tags ExtractUserTags();
@@ -178,4 +179,5 @@ class Configuration final : public IConfiguration
 
     CpuProfilerType _cpuProfilerType;
     std::chrono::milliseconds _cpuProfilingInterval;
+    bool _isWaitHandleProfilingEnabled;
 };