[Test Optimization] perf: logging/timing helpers

tracer/src/Datadog.Trace/Ci/Agent/CIVisibilityProtocolWriter.cs

@@ -74,7 +74,7 @@ internal sealed class CIVisibilityProtocolWriter : IEventWriter
     public CIVisibilityProtocolWriter(
         TestOptimizationSettings settings,
         ICIVisibilityProtocolWriterSender sender,
-        IFormatterResolver? formatterResolver = null,
+        IFormatterResolver formatterResolver,
         int? concurrency = null,
         int batchInterval = DefaultBatchInterval,
         int maxItemsInQueue = DefaultMaxItemsInQueue)
@@ -90,15 +90,15 @@ public CIVisibilityProtocolWriter(
         {
             var buffers = new Buffers(
                 sender,
-                new CITestCyclePayload(settings, formatterResolver: formatterResolver),
-                new CICodeCoveragePayload(settings, formatterResolver: formatterResolver));
+                new CITestCyclePayload(settings, formatterResolver),
+                new CICodeCoveragePayload(settings, formatterResolver));
             _buffersArray[i] = buffers;
             var tskFlush = Task.Run(() => InternalFlushEventsAsync(this, buffers));
             tskFlush.ContinueWith(t => Log.Error(t.Exception, "CIVisibilityProtocolWriter: Error in sending ci visibility events"), TaskContinuationOptions.OnlyOnFaulted);
             _buffersArray[i].SetFlushTask(tskFlush);
         }
 
-        Log.Information<int>("CIVisibilityProtocolWriter Initialized with concurrency level of: {ConcurrencyLevel}", concurrencyLevel);
+        Log.Debug<int>("CIVisibilityProtocolWriter Initialized with concurrency level of: {ConcurrencyLevel}", concurrencyLevel);
     }
 
     public void WriteEvent(IEvent @event)
@@ -349,7 +349,7 @@ internal void SetFlushTask(Task flushTask)
 
         public Task FlushCiTestCycleBufferWhenTimeElapsedAsync(int batchInterval)
         {
-            return CiTestCycleBufferWatch.ElapsedMilliseconds >= batchInterval ?
+            return CiTestCycleBufferWatch.GetElapsedMilliseconds() >= batchInterval ?
                        FlushCiTestCycleBufferAsync() : Task.CompletedTask;
         }
 
@@ -367,7 +367,7 @@ async Task InternalFlushCiTestCycleBufferAsync()
 
         public Task FlushCiCodeCoverageBufferWhenTimeElapsedAsync(int batchInterval)
         {
-            return CiCodeCoverageBufferWatch.ElapsedMilliseconds >= batchInterval ?
+            return CiCodeCoverageBufferWatch.GetElapsedMilliseconds() >= batchInterval ?
                        FlushCiCodeCoverageBufferAsync() : Task.CompletedTask;
         }
 

tracer/src/Datadog.Trace/Ci/Agent/CIWriterHttpSender.cs

@@ -16,6 +16,7 @@
 using Datadog.Trace.Configuration;
 using Datadog.Trace.Logging;
 using Datadog.Trace.Telemetry;
+using Datadog.Trace.Util;
 using Datadog.Trace.Util.Http;
 using Datadog.Trace.Vendors.Serilog.Events;
 
@@ -34,7 +35,7 @@ public CIWriterHttpSender(IApiRequestFactory apiRequestFactory)
     {
         _apiRequestFactory = apiRequestFactory;
         _isDebugEnabled = GlobalSettings.Instance.DebugEnabled;
-        Log.Information("CIWriterHttpSender Initialized.");
+        Log.Debug("CIWriterHttpSender Initialized.");
     }
 
     public Task SendPayloadAsync(EventPlatformPayload payload)
@@ -146,7 +147,7 @@ private async Task SendPayloadAsync<T>(EventPlatformPayload payload, Func<IApiRe
             }
             finally
             {
-                TelemetryFactory.Metrics.RecordDistributionCIVisibilityEndpointPayloadRequestsMs(payload.TelemetryEndpoint, sw.Elapsed.TotalMilliseconds);
+                TelemetryFactory.Metrics.RecordDistributionCIVisibilityEndpointPayloadRequestsMs(payload.TelemetryEndpoint, sw.GetElapsedMilliseconds());
                 if (TelemetryHelper.GetErrorTypeFromStatusCode(statusCode) is { } errorType)
                 {
                     TelemetryFactory.Metrics.RecordCountCIVisibilityEndpointPayloadRequestsErrors(payload.TelemetryEndpoint, errorType);

tracer/src/Datadog.Trace/Ci/Agent/Payloads/CICodeCoveragePayload.cs

@@ -6,29 +6,26 @@
 #nullable enable
 
 using System;
-using System.Diagnostics;
 using System.Text;
 using Datadog.Trace.Agent;
 using Datadog.Trace.Agent.Transports;
-using Datadog.Trace.Ci.Agent.MessagePack;
 using Datadog.Trace.Ci.Configuration;
 using Datadog.Trace.Ci.Coverage.Models.Tests;
 using Datadog.Trace.Telemetry;
 using Datadog.Trace.Telemetry.Metrics;
+using Datadog.Trace.Util;
 using Datadog.Trace.Vendors.MessagePack;
 
 namespace Datadog.Trace.Ci.Agent.Payloads;
 
 internal sealed class CICodeCoveragePayload : MultipartPayload
 {
     private readonly IFormatterResolver _formatterResolver;
-    private readonly Stopwatch _serializationWatch;
 
-    public CICodeCoveragePayload(TestOptimizationSettings settings, int maxItemsPerPayload = DefaultMaxItemsPerPayload, int maxBytesPerPayload = DefaultMaxBytesPerPayload, IFormatterResolver? formatterResolver = null)
-        : base(settings, maxItemsPerPayload, maxBytesPerPayload, formatterResolver)
+    public CICodeCoveragePayload(TestOptimizationSettings settings, IFormatterResolver formatterResolver, int maxItemsPerPayload = DefaultMaxItemsPerPayload, int maxBytesPerPayload = DefaultMaxBytesPerPayload)
+        : base(settings, formatterResolver, maxItemsPerPayload, maxBytesPerPayload)
     {
-        _formatterResolver = formatterResolver ?? CIFormatterResolver.Instance;
-        _serializationWatch = new Stopwatch();
+        _formatterResolver = formatterResolver;
 
         // We call reset here to add the dummy event
         Reset();
@@ -62,14 +59,14 @@ protected override MultipartFormItem CreateMultipartFormItem(EventsBuffer<IEvent
 
     public override bool TryProcessEvent(IEvent @event)
     {
-        _serializationWatch.Restart();
+        var sw = RefStopwatch.Create();
         var success = base.TryProcessEvent(@event);
         if (success && @event is TestCoverage)
         {
             TestCoverageEventsCount++;
         }
 
-        TelemetryFactory.Metrics.RecordDistributionCIVisibilityEndpointEventsSerializationMs(TelemetryEndpoint, _serializationWatch.Elapsed.TotalMilliseconds);
+        TelemetryFactory.Metrics.RecordDistributionCIVisibilityEndpointEventsSerializationMs(TelemetryEndpoint, sw.ElapsedMilliseconds);
         return success;
     }
 

tracer/src/Datadog.Trace/Ci/Agent/Payloads/CITestCyclePayload.cs

@@ -13,7 +13,7 @@ namespace Datadog.Trace.Ci.Agent.Payloads;
 
 internal sealed class CITestCyclePayload : CIVisibilityProtocolPayload
 {
-    public CITestCyclePayload(TestOptimizationSettings settings, IFormatterResolver? formatterResolver = null)
+    public CITestCyclePayload(TestOptimizationSettings settings, IFormatterResolver formatterResolver)
         : base(settings, formatterResolver)
     {
     }

tracer/src/Datadog.Trace/Ci/Agent/Payloads/CIVisibilityProtocolPayload.cs

@@ -4,12 +4,11 @@
 // </copyright>
 #nullable enable
 
-using System.Diagnostics;
 using System.IO;
-using Datadog.Trace.Ci.Agent.MessagePack;
 using Datadog.Trace.Ci.Configuration;
 using Datadog.Trace.Ci.EventModel;
 using Datadog.Trace.Telemetry;
+using Datadog.Trace.Util;
 using Datadog.Trace.Vendors.MessagePack;
 
 namespace Datadog.Trace.Ci.Agent.Payloads;
@@ -18,13 +17,11 @@ internal abstract class CIVisibilityProtocolPayload : EventPlatformPayload
 {
     private readonly EventsBuffer<IEvent> _events;
     private readonly IFormatterResolver _formatterResolver;
-    private readonly Stopwatch _serializationWatch;
 
-    public CIVisibilityProtocolPayload(TestOptimizationSettings settings, IFormatterResolver? formatterResolver = null)
+    public CIVisibilityProtocolPayload(TestOptimizationSettings settings, IFormatterResolver formatterResolver)
         : base(settings)
     {
-        _formatterResolver = formatterResolver ?? CIFormatterResolver.Instance;
-        _serializationWatch = new Stopwatch();
+        _formatterResolver = formatterResolver;
 
         // Because we don't know the size of the events array envelope we left 500kb for that.
         _events = new EventsBuffer<IEvent>(settings.MaximumAgentlessPayloadSize - (500 * 1024), _formatterResolver);
@@ -48,7 +45,7 @@ public CIVisibilityProtocolPayload(TestOptimizationSettings settings, IFormatter
 
     public override bool TryProcessEvent(IEvent @event)
     {
-        _serializationWatch.Restart();
+        var sw = RefStopwatch.Create();
         var success = _events.TryWrite(@event);
         if (success)
         {
@@ -74,7 +71,7 @@ public override bool TryProcessEvent(IEvent @event)
             }
         }
 
-        TelemetryFactory.Metrics.RecordDistributionCIVisibilityEndpointEventsSerializationMs(TelemetryEndpoint, _serializationWatch.Elapsed.TotalMilliseconds);
+        TelemetryFactory.Metrics.RecordDistributionCIVisibilityEndpointEventsSerializationMs(TelemetryEndpoint, sw.ElapsedMilliseconds);
         return success;
     }
 

tracer/src/Datadog.Trace/Ci/Agent/Payloads/MultipartPayload.cs

@@ -7,7 +7,6 @@
 using System;
 using System.Collections.Generic;
 using Datadog.Trace.Agent;
-using Datadog.Trace.Ci.Agent.MessagePack;
 using Datadog.Trace.Ci.Configuration;
 using Datadog.Trace.Vendors.MessagePack;
 
@@ -21,11 +20,9 @@ internal abstract class MultipartPayload : EventPlatformPayload
 
     private readonly EventsBuffer<IEvent> _events;
     private readonly List<MultipartFormItem> _items;
-    private readonly IFormatterResolver _formatterResolver;
     private readonly int _maxItemsPerPayload;
-    private readonly int _maxBytesPerPayload;
 
-    public MultipartPayload(TestOptimizationSettings settings, int maxItemsPerPayload = DefaultMaxItemsPerPayload, int maxBytesPerPayload = DefaultMaxBytesPerPayload, IFormatterResolver? formatterResolver = null)
+    public MultipartPayload(TestOptimizationSettings settings, IFormatterResolver formatterResolver, int maxItemsPerPayload = DefaultMaxItemsPerPayload, int maxBytesPerPayload = DefaultMaxBytesPerPayload)
         : base(settings)
     {
         if (maxBytesPerPayload < HeaderSize)
@@ -34,12 +31,10 @@ public MultipartPayload(TestOptimizationSettings settings, int maxItemsPerPayloa
         }
 
         _maxItemsPerPayload = maxItemsPerPayload;
-        _maxBytesPerPayload = maxBytesPerPayload;
-        _formatterResolver = formatterResolver ?? CIFormatterResolver.Instance;
         _items = new List<MultipartFormItem>(Math.Min(maxItemsPerPayload, DefaultMaxItemsPerPayload));
 
         // Because we don't know the size of the events array envelope we left 1024kb for that.
-        _events = new EventsBuffer<IEvent>(Math.Min(_maxBytesPerPayload, DefaultMaxBytesPerPayload) - HeaderSize, _formatterResolver);
+        _events = new EventsBuffer<IEvent>(Math.Min(maxBytesPerPayload, DefaultMaxBytesPerPayload) - HeaderSize, formatterResolver);
     }
 
     public override bool HasEvents => _events.Count > 0;

tracer/src/Datadog.Trace/Ci/Coverage/DefaultWithGlobalCoverageEventHandler.cs

@@ -13,6 +13,7 @@
 using Datadog.Trace.Ci.Coverage.Models.Global;
 using Datadog.Trace.Ci.Coverage.Util;
 using Datadog.Trace.Telemetry;
+using Datadog.Trace.Util;
 using Datadog.Trace.Vendors.Newtonsoft.Json;
 using Datadog.Trace.Vendors.Serilog.Events;
 
@@ -54,7 +55,7 @@ public unsafe GlobalCoverageInfo GetCodeCoveragePercentage()
         {
             lock (_coverages)
             {
-                var sw = Stopwatch.StartNew();
+                var sw = RefStopwatch.Create();
                 var globalCoverage = new GlobalCoverageInfo();
 
                 IEnumerable<ModuleValue> GetModuleValues()
@@ -151,7 +152,7 @@ IEnumerable<ModuleValue> GetModuleValues()
                 // Clean coverages
                 Clear();
 
-                Log.Information("Total time to calculate global coverage: {TotalMilliseconds}ms", sw.Elapsed.TotalMilliseconds);
+                Log.Information("Total time to calculate global coverage: {TotalMilliseconds}ms", sw.ElapsedMilliseconds);
                 return globalCoverage;
             }
         }

tracer/src/Datadog.Trace/Ci/Processors/OriginTagTraceProcessor.cs

@@ -27,7 +27,7 @@ public OriginTagTraceProcessor(bool isPartialFlushEnabled, bool isCiVisibilityPr
             _isPartialFlushEnabled = isPartialFlushEnabled;
             _isCiVisibilityProtocol = isCiVisibilityProtocol;
 
-            Log.Information("OriginTraceProcessor initialized.");
+            Log.Debug("OriginTraceProcessor initialized.");
         }
 
         public SpanCollection Process(in SpanCollection trace)

tracer/src/Datadog.Trace/Ci/Processors/TestSuiteVisibilityProcessor.cs

@@ -19,7 +19,7 @@ internal sealed class TestSuiteVisibilityProcessor : ITraceProcessor
 
     public TestSuiteVisibilityProcessor()
     {
-        Log.Information("TestSuiteVisibilityProcessor initialized.");
+        Log.Debug("TestSuiteVisibilityProcessor initialized.");
     }
 
     public SpanCollection Process(in SpanCollection trace)

tracer/src/Datadog.Trace/Ci/TestOptimizationTracerManagerFactory.cs

@@ -10,6 +10,7 @@
 using Datadog.Trace.Agent;
 using Datadog.Trace.Agent.DiscoveryService;
 using Datadog.Trace.Ci.Agent;
+using Datadog.Trace.Ci.Agent.MessagePack;
 using Datadog.Trace.Ci.Configuration;
 using Datadog.Trace.Ci.Sampling;
 using Datadog.Trace.Configuration;
@@ -22,7 +23,6 @@
 using Datadog.Trace.RuntimeMetrics;
 using Datadog.Trace.Sampling;
 using Datadog.Trace.Telemetry;
-using Datadog.Trace.Vendors.StatsdClient;
 
 namespace Datadog.Trace.Ci
 {
@@ -97,7 +97,7 @@ protected override IAgentWriter GetAgentWriter(TracerSettings settings, IStatsdM
             {
                 if (!string.IsNullOrEmpty(_settings.ApiKey))
                 {
-                    return new CIVisibilityProtocolWriter(_settings, new CIWriterHttpSender(_testOptimizationTracerManagement.GetRequestFactory(settings)));
+                    return new CIVisibilityProtocolWriter(_settings, new CIWriterHttpSender(_testOptimizationTracerManagement.GetRequestFactory(settings)), CIFormatterResolver.Instance);
                 }
 
                 Environment.FailFast("An API key is required in Agentless mode.");
@@ -107,7 +107,7 @@ protected override IAgentWriter GetAgentWriter(TracerSettings settings, IStatsdM
             // With agent scenario:
             if (_enabledEventPlatformProxy)
             {
-                return new CIVisibilityProtocolWriter(_settings, new CIWriterHttpSender(_testOptimizationTracerManagement.GetRequestFactory(settings)));
+                return new CIVisibilityProtocolWriter(_settings, new CIWriterHttpSender(_testOptimizationTracerManagement.GetRequestFactory(settings)), CIFormatterResolver.Instance);
             }
 
             // Event platform proxy not found

tracer/src/Datadog.Trace/ClrProfiler/Instrumentation.cs

@@ -123,6 +123,8 @@ private static void PropagateStableConfiguration()
         /// </summary>
         public static void Initialize()
         {
+            using var cd = CodeDurationRef.Create();
+
             if (Interlocked.Exchange(ref _firstInitialization, 0) != 1)
             {
                 // Initialize() was already called before
@@ -133,10 +135,10 @@ public static void Initialize()
             {
                 TracerDebugger.WaitForDebugger();
 
-                var swTotal = Stopwatch.StartNew();
+                var swTotal = RefStopwatch.Create();
                 Log.Debug("Initialization started.");
 
-                var sw = Stopwatch.StartNew();
+                var sw = RefStopwatch.Create();
 
                 bool versionMismatch = GetNativeTracerVersion() != TracerConstants.ThreePartVersion;
                 if (versionMismatch)
@@ -145,7 +147,7 @@ public static void Initialize()
                 }
                 else
                 {
-                    InitializeNoNativeParts(sw);
+                    InitializeNoNativeParts(ref sw);
 
                     try
                     {
@@ -196,7 +198,7 @@ public static void Initialize()
                     TelemetryFactory.Metrics.RecordDistributionSharedInitTime(MetricTags.InitializationComponent.CallTargetDefsPinvoke, sw.ElapsedMilliseconds);
                     sw.Restart();
 
-                    InitializeTracer(sw);
+                    InitializeTracer(ref sw);
                 }
 
 #if NETSTANDARD2_0 || NETCOREAPP3_1
@@ -263,7 +265,7 @@ private static void RunShutdown(Exception ex)
             NativeCallTargetUnmanagedMemoryHelper.Free();
         }
 
-        internal static void InitializeNoNativeParts(Stopwatch sw = null)
+        internal static void InitializeNoNativeParts(ref RefStopwatch sw)
         {
             if (Interlocked.Exchange(ref _firstNonNativePartsInitialization, 0) != 1)
             {
@@ -423,14 +425,11 @@ internal static void InitializeNoNativeParts(Stopwatch sw = null)
                 Log.Debug("Tracer.Instance is null after InitializeNoNativeParts was invoked");
             }
 
-            if (sw != null)
-            {
-                TelemetryFactory.Metrics.RecordDistributionSharedInitTime(MetricTags.InitializationComponent.Managed, sw.ElapsedMilliseconds);
-                sw.Restart();
-            }
+            TelemetryFactory.Metrics.RecordDistributionSharedInitTime(MetricTags.InitializationComponent.Managed, sw.ElapsedMilliseconds);
+            sw.Restart();
         }
 
-        private static void InitializeTracer(Stopwatch sw)
+        private static void InitializeTracer(ref RefStopwatch sw)
         {
             var tracer = Tracer.Instance;
             if (tracer is null)

tracer/src/Datadog.Trace/Logging/Internal/DatadogLogging.cs

@@ -54,7 +54,11 @@ static DatadogLogging()
         public static IDatadogLogger GetLoggerFor(Type classType)
         {
             // Tells us which types are loaded, when, and how often.
-            SharedLogger.Debug("Logger retrieved for: {AssemblyQualifiedName}", classType.AssemblyQualifiedName);
+            if (SharedLogger.IsEnabled(LogEventLevel.Debug))
+            {
+                SharedLogger.Debug("Logger retrieved for: {AssemblyQualifiedName}", classType.AssemblyQualifiedName);
+            }
+
             return SharedLogger;
         }