Improve timestamp precision of transactions and spans (#1680)

Author: mattjohnsonpint

CHANGELOG.md

@@ -5,6 +5,7 @@
 ### Fixes
 
 - Flatten AggregateException ([#1672](https://github.com/getsentry/sentry-dotnet/pull/1672))
+- Improve timestamp precision of transactions and spans ([#1680](https://github.com/getsentry/sentry-dotnet/pull/1680))
 
 ### Features
 

src/Sentry/Internal/SentryStopwatch.cs

@@ -0,0 +1,38 @@
+using System;
+using System.Diagnostics;
+
+namespace Sentry.Internal
+{
+    /// <summary>
+    /// This is a struct-based alternative to <see cref="System.Diagnostics.Stopwatch"/>.
+    /// It avoids unnecessary allocations and includes realtime clock values.
+    /// </summary>
+    internal struct SentryStopwatch
+    {
+        private static readonly double StopwatchTicksPerTimeSpanTick =
+            (double)Stopwatch.Frequency / TimeSpan.TicksPerSecond;
+
+        private long _startTimestamp;
+        private DateTimeOffset _startDateTimeOffset;
+
+        public static SentryStopwatch StartNew() => new()
+        {
+            _startTimestamp = Stopwatch.GetTimestamp(),
+            _startDateTimeOffset = DateTimeOffset.UtcNow
+        };
+
+        public DateTimeOffset StartDateTimeOffset => _startDateTimeOffset;
+        public DateTimeOffset CurrentDateTimeOffset => _startDateTimeOffset + Elapsed;
+
+        public TimeSpan Elapsed
+        {
+            get
+            {
+                var now = Stopwatch.GetTimestamp();
+                var diff = now - _startTimestamp;
+                var ticks = (long)(diff / StopwatchTicksPerTimeSpanTick);
+                return TimeSpan.FromTicks(ticks);
+            }
+        }
+    }
+}

src/Sentry/Span.cs

@@ -66,7 +66,7 @@ public void SetExtra(string key, object? value) =>
             (_extra ??= new Dictionary<string, object?>())[key] = value;
 
         /// <summary>
-        /// Initializes an instance of <see cref="SpanTracer"/>.
+        /// Initializes an instance of <see cref="Span"/>.
         /// </summary>
         public Span(SpanId? parentSpanId, string operation)
         {
@@ -77,7 +77,7 @@ public Span(SpanId? parentSpanId, string operation)
         }
 
         /// <summary>
-        /// Initializes an instance of <see cref="SpanTracer"/>.
+        /// Initializes an instance of <see cref="Span"/>.
         /// </summary>
         public Span(ISpan tracer)
             : this(tracer.ParentSpanId, tracer.Operation)

src/Sentry/SpanTracer.cs

@@ -1,6 +1,7 @@
 using System;
 using System.Collections.Concurrent;
 using System.Collections.Generic;
+using Sentry.Internal;
 
 namespace Sentry
 {
@@ -11,6 +12,7 @@ public class SpanTracer : ISpan
     {
         private readonly IHub _hub;
         private readonly TransactionTracer _transaction;
+        private readonly SentryStopwatch _stopwatch = SentryStopwatch.StartNew();
 
         /// <inheritdoc />
         public SpanId SpanId { get; }
@@ -22,7 +24,7 @@ public class SpanTracer : ISpan
         public SentryId TraceId { get; }
 
         /// <inheritdoc />
-        public DateTimeOffset StartTimestamp { get; } = DateTimeOffset.UtcNow;
+        public DateTimeOffset StartTimestamp => _stopwatch.StartDateTimeOffset;
 
         /// <inheritdoc />
         public DateTimeOffset? EndTimestamp { get; private set; }
@@ -91,7 +93,7 @@ public ISpan StartChild(string operation) =>
         public void Finish()
         {
             Status ??= SpanStatus.UnknownError;
-            EndTimestamp = DateTimeOffset.UtcNow;
+            EndTimestamp = _stopwatch.CurrentDateTimeOffset;
         }
 
         /// <inheritdoc />

src/Sentry/TransactionTracer.cs

@@ -2,6 +2,7 @@
 using System.Collections.Concurrent;
 using System.Collections.Generic;
 using System.Linq;
+using Sentry.Internal;
 
 namespace Sentry
 {
@@ -11,6 +12,7 @@ namespace Sentry
     public class TransactionTracer : ITransaction
     {
         private readonly IHub _hub;
+        private readonly SentryStopwatch _stopwatch = SentryStopwatch.StartNew();
 
         /// <inheritdoc />
         public SpanId SpanId
@@ -50,7 +52,7 @@ public SentryId TraceId
         public string? Release { get; set; }
 
         /// <inheritdoc />
-        public DateTimeOffset StartTimestamp { get; } = DateTimeOffset.UtcNow;
+        public DateTimeOffset StartTimestamp => _stopwatch.StartDateTimeOffset;
 
         /// <inheritdoc />
         public DateTimeOffset? EndTimestamp { get; internal set; }
@@ -170,8 +172,10 @@ public TransactionTracer(IHub hub, string name, string operation)
         /// Initializes an instance of <see cref="Transaction"/>.
         /// </summary>
         public TransactionTracer(IHub hub, ITransactionContext context)
-            : this(hub, context.Name, context.Operation)
         {
+            _hub = hub;
+            Name = context.Name;
+            Operation = context.Operation;
             SpanId = context.SpanId;
             ParentSpanId = context.ParentSpanId;
             TraceId = context.TraceId;
@@ -224,7 +228,7 @@ public ISpan StartChild(string operation) =>
         public void Finish()
         {
             Status ??= SpanStatus.UnknownError;
-            EndTimestamp = DateTimeOffset.UtcNow;
+            EndTimestamp = _stopwatch.CurrentDateTimeOffset;
 
             foreach (var span in _spans)
             {

test/Sentry.Tests/Internals/SentryStopwatchTests.cs

@@ -0,0 +1,39 @@
+namespace Sentry.Tests.Internals;
+
+public class SentryStopwatchTests
+{
+    // Note: We can really can't test this at fine precision.  This is just to make sure we're in the right ballpark.
+    private static readonly TimeSpan TestPrecision = TimeSpan.FromMilliseconds(500);
+
+    [Fact]
+    public void StartDateTimeOffset_IsValid()
+    {
+        var sw = SentryStopwatch.StartNew();
+        var start = sw.StartDateTimeOffset;
+
+        start.Should().BeCloseTo(DateTimeOffset.UtcNow, TestPrecision);
+    }
+
+    [Fact]
+    public void CurrentDateTimeOffset_IsValid()
+    {
+        var sw = SentryStopwatch.StartNew();
+        Thread.Sleep(TimeSpan.FromMilliseconds(100));
+        var current = sw.CurrentDateTimeOffset;
+
+        current.Should().BeCloseTo(DateTimeOffset.UtcNow, TestPrecision);
+    }
+
+    [Fact]
+    public void Elapsed_IsValid()
+    {
+        var sleepTime = TimeSpan.FromMilliseconds(100);
+
+        var sw = SentryStopwatch.StartNew();
+        Thread.Sleep(sleepTime);
+        var elapsed = sw.Elapsed;
+
+        elapsed.Should().BeGreaterThan(TimeSpan.Zero);
+        elapsed.Should().BeCloseTo(sleepTime, TestPrecision);
+    }
+}