[Profiler] Fix flakiness due to Libraries Info Cache (#8997)

Author: gleocadie

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

@@ -56,6 +56,14 @@ bool AutoResetEvent::Wait(std::chrono::milliseconds timeout)
         clock_gettime(CLOCK_REALTIME, &ts);
         ts.tv_nsec += timeout.count() % 1000 * 1'000'000;
         ts.tv_sec += timeout.count() / 1000;
+
+        // pthread_cond_timedwait rejects tv_nsec >= 1s with EINVAL, which this loop would
+        // spin on instead of timing out. Both operands are < 1s, so one carry is enough.
+        if (ts.tv_nsec >= 1'000'000'000)
+        {
+            ts.tv_nsec -= 1'000'000'000;
+            ts.tv_sec += 1;
+        }
     }
 
     while(!_impl->_isSet)

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

@@ -152,7 +152,8 @@ LibrariesInfoCache::LibrariesInfoCache(IConfiguration* configuration, shared::pm
     _newSymbols{_wrappersAllocator},
 #endif
     _stopRequested{false},
-    _event(true)
+    _event(true),
+    _startTimeout(configuration->GetLibrariesInfoCacheStartTimeout())
 {
     if (_tracker)
     {
@@ -186,17 +187,11 @@ bool LibrariesInfoCache::StartImpl()
 
     // Wait for the thread to be fully started and the cache populated
     // before setting s_instance and registering with libunwind.
-    // Cache population can be slow under sanitizers (ASAN/UBSAN add overhead to
-    // every allocation and memory access) — use a longer timeout in that case.
-#if defined(DD_SANITIZERS)
-    constexpr auto startTimeout = 10s;
-#else
-    constexpr auto startTimeout = 2s;
-#endif
-    if (!startEvent->Wait(startTimeout))
+
+    if (!startEvent->Wait(_startTimeout))
     {
-        Log::Error("Failed to populate LibrariesInfoCache within timeout. "
-                   "Not registering custom iterate_phdr_function with libunwind.");
+        Log::Error("Failed to populate LibrariesInfoCache within timeout: ", _startTimeout,
+                   ". Not registering custom iterate_phdr_function with libunwind.");
         _stopRequested = true;
         _event.Set();
         _worker.join();

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

@@ -13,6 +13,7 @@
 #include "shared/src/native-src/dd_memory_resource.hpp"
 
 #include <atomic>
+#include <chrono>
 #include <link.h>
 #include <memory>
 #include <shared_mutex>
@@ -122,4 +123,7 @@ class LibrariesInfoCache : public ServiceBase
     std::thread _worker;
     std::atomic<bool> _stopRequested;
     AutoResetEvent _event;
+    // How long StartImpl waits for the first cache population. Longer on slow/loaded
+    // machines (CI), where the default is not enough and the cache is silently skipped.
+    std::chrono::milliseconds _startTimeout;
 };

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

@@ -35,6 +35,14 @@ CpuProfilerType const Configuration::DefaultCpuProfilerType =
 #endif
 std::chrono::minutes const Configuration::DefaultDevHeapSnapshotInterval = 1min;
 std::chrono::minutes const Configuration::DefaultProdHeapSnapshotInterval = 5min;
+std::chrono::milliseconds const Configuration::DefaultLibrariesInfoCacheStartTimeout =
+#if defined(DD_SANITIZERS)
+    // Sanitizers instrument every allocation and memory access, so populating the
+    // cache takes considerably longer than in a regular build.
+    10s;
+#else
+    2s;
+#endif
 
 Configuration::Configuration()
 {
@@ -126,6 +134,7 @@ Configuration::Configuration()
     _heapSnapshotCheckInterval = ExtractHeapSnapshotCheckInterval();
     _heapSnapshotMemoryPressureThreshold = GetEnvironmentValue(EnvironmentVariables::HeapSnapshotMemoryPressureThreshold, 50);
     _testHeapSnapshotInterval = ExtractTestHeapSnapshotInterval();
+    _librariesInfoCacheStartTimeout = ExtractLibrariesInfoCacheStartTimeout();
     _heapHandleLimit = ExtractHeapHandleLimit();
     bool defaultUseManagedCodeCache =
     #if ARM64
@@ -937,6 +946,27 @@ std::chrono::seconds Configuration::GetTestHeapSnapshotInterval() const
     return _testHeapSnapshotInterval;
 }
 
+std::chrono::milliseconds Configuration::ExtractLibrariesInfoCacheStartTimeout() const
+{
+    // A negative value parses into a negative duration, and zero would make the wait
+    // return immediately, silently disabling the cache: neither is ever intended.
+    auto timeout = GetEnvironmentValue(EnvironmentVariables::LibrariesInfoCacheStartTimeout, DefaultLibrariesInfoCacheStartTimeout);
+    if (timeout <= 0ms)
+    {
+        Log::Warn("Configuration: ", EnvironmentVariables::LibrariesInfoCacheStartTimeout,
+                  " env var must be strictly positive but is set to '", timeout,
+                  "' - '", DefaultLibrariesInfoCacheStartTimeout, "' is used instead");
+        return DefaultLibrariesInfoCacheStartTimeout;
+    }
+
+    return timeout;
+}
+
+std::chrono::milliseconds Configuration::GetLibrariesInfoCacheStartTimeout() const
+{
+    return _librariesInfoCacheStartTimeout;
+}
+
 int32_t Configuration::ExtractHeapHandleLimit() const
 {
     // default handle count limit is 4096; could be changed via env vars from 1024 to 16000

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

@@ -90,6 +90,7 @@ class Configuration final : public IConfiguration
     std::chrono::milliseconds GetHeapSnapshotCheckInterval() const override;
     uint32_t GetHeapSnapshotMemoryPressureThreshold() const override;
     std::chrono::seconds GetTestHeapSnapshotInterval() const override;
+    std::chrono::milliseconds GetLibrariesInfoCacheStartTimeout() const override;
     uint32_t GetHeapHandleLimit() const override;
     bool UseManagedCodeCache() const override;
     bool IsMemoryFootprintEnabled() const override;
@@ -123,6 +124,7 @@ class Configuration final : public IConfiguration
     std::chrono::milliseconds ExtractHeapSnapshotCheckInterval() const;
     std::chrono::minutes GetDefaultHeapSnapshotInterval() const;
     std::chrono::seconds ExtractTestHeapSnapshotInterval() const;
+    std::chrono::milliseconds ExtractLibrariesInfoCacheStartTimeout() const;
     int32_t ExtractHeapHandleLimit() const;
     uint32_t ExtractReferenceTreeFormat() const;
 
@@ -140,6 +142,7 @@ class Configuration final : public IConfiguration
     static CpuProfilerType const DefaultCpuProfilerType;
     static std::chrono::minutes const DefaultDevHeapSnapshotInterval;
     static std::chrono::minutes const DefaultProdHeapSnapshotInterval;
+    static std::chrono::milliseconds const DefaultLibrariesInfoCacheStartTimeout;
 
     bool _isProfilingEnabled;
     bool _isCpuProfilingEnabled;
@@ -211,6 +214,7 @@ class Configuration final : public IConfiguration
     std::chrono::milliseconds _heapSnapshotCheckInterval;
     uint32_t _heapSnapshotMemoryPressureThreshold; // in % of used memory
     std::chrono::seconds _testHeapSnapshotInterval;
+    std::chrono::milliseconds _librariesInfoCacheStartTimeout;
     bool _useManagedCodeCache;
     bool _isMemoryFootprintEnabled;
     uint32_t _referenceTreeFormat;

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

@@ -85,6 +85,7 @@ class EnvironmentVariables final
     // used for tests only
     inline static const shared::WSTRING ForceHttpSampling           = WStr("DD_INTERNAL_PROFILING_FORCE_HTTP_SAMPLING");
     inline static const shared::WSTRING TestHeapSnapshotInterval    = WStr("DD_INTERNAL_PROFILING_TEST_HEAPSNAPSHOT_INTERVAL");
+    inline static const shared::WSTRING LibrariesInfoCacheStartTimeout = WStr("DD_INTERNAL_PROFILING_LIBRARIES_CACHE_START_TIMEOUT");
 
     inline static const shared::WSTRING CIVisibilityEnabled         = WStr("DD_CIVISIBILITY_ENABLED");
     inline static const shared::WSTRING InternalCIVisibilitySpanId  = WStr("DD_INTERNAL_CIVISIBILITY_SPANID");

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

@@ -89,6 +89,7 @@ class IConfiguration
     virtual std::chrono::milliseconds GetHeapSnapshotCheckInterval() const = 0;
     virtual uint32_t GetHeapSnapshotMemoryPressureThreshold() const = 0;
     virtual std::chrono::seconds GetTestHeapSnapshotInterval() const = 0;
+    virtual std::chrono::milliseconds GetLibrariesInfoCacheStartTimeout() const = 0;
     virtual uint32_t GetHeapHandleLimit() const = 0;
     virtual bool UseManagedCodeCache() const = 0;
     virtual bool IsMemoryFootprintEnabled() const = 0;

profiler/test/Datadog.Profiler.IntegrationTests/Helpers/EnvironmentHelper.cs

@@ -195,6 +195,10 @@ internal void PopulateEnvironmentVariables(StringDictionary environmentVariables
             // Linux ARM64: native profiler requires DD_INTERNAL_PROFILING_ENABLED_ARM64; align managed enablement.
             environmentVariables["DD_INTERNAL_PROFILING_ENABLED_ARM64"] = "1";
 
+            // Test machines are slow and loaded enough that the default 2s is not always enough to
+            // populate the libraries cache, and the profiler silently falls back to slower unwinding.
+            environmentVariables[EnvironmentVariables.LibrariesInfoCacheStartTimeout] = "10000";
+
             environmentVariables["DD_TRACE_ENABLED"] = "0";
 
             environmentVariables["DD_PROFILING_UPLOAD_PERIOD"] = profilingExportIntervalInSeconds.ToString();

profiler/test/Datadog.Profiler.IntegrationTests/Helpers/EnvironmentVariables.cs

@@ -47,5 +47,6 @@ internal class EnvironmentVariables
         public const string TestHeapSnapshotInterval = "DD_INTERNAL_PROFILING_TEST_HEAPSNAPSHOT_INTERVAL";
         public const string UseManagedCodeCache = "DD_INTERNAL_PROFILING_USE_MANAGED_CODE_CACHE";
         public const string MemoryFootprintEnabled = "DD_INTERNAL_PROFILING_MEMORY_FOOTPRINT_ENABLED";
+        public const string LibrariesInfoCacheStartTimeout = "DD_INTERNAL_PROFILING_LIBRARIES_CACHE_START_TIMEOUT";
     }
 }

profiler/test/Datadog.Profiler.Native.Tests/AutoResetEventTest.cpp

@@ -6,6 +6,8 @@
 #include "profiler/src/ProfilerEngine/Datadog.Profiler.Native/AutoResetEvent.h"
 
 #include <future>
+#include <thread>
+#include <time.h>
 
 #include "gtest/gtest.h"
 
@@ -130,6 +132,23 @@ TEST(AutoResetEventTest, EnsureEventIsSignaledIfSetIsCalledWhileWaitingWithTimeo
     ASSERT_DURATION_LE(50ms, event->Set());
 }
 
+TEST(AutoResetEventTest, EnsureTimeoutExpiresWhenSubSecondTimeoutOverflowsCurrentSecond)
+{
+    // The timeout is added to the current wall clock, so the sub-second part of that sum
+    // only overflows into the next second when the clock is already late enough in the
+    // current one. Wait for that window, keeping enough margin to still be in it below.
+    struct timespec now;
+    do
+    {
+        std::this_thread::sleep_for(1ms);
+        clock_gettime(CLOCK_REALTIME, &now);
+    } while (now.tv_nsec < 900'000'000 || now.tv_nsec > 980'000'000);
+
+    auto event = CreateEvent(false);
+    ASSERT_DURATION_LE(500ms, event->Wait(200ms));
+    ASSERT_FALSE(event->IsSet());
+}
+
 TEST(AutoResetEventTest, CheckCaseWhenEventHasTimeOutButSignaledLater)
 {
     auto event = CreateEvent(false);