Skip to content

Commit 53ccbed

Browse files
bmermetbmermet
committed
Fix time alignments bug
1 parent 707b3ec commit 53ccbed

File tree

5 files changed

+73
-47
lines changed

5 files changed

+73
-47
lines changed

‎src/Datadog.Trace.Tests/SpanTests.cs‎

Lines changed: 13 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -8,15 +8,14 @@ namespace Datadog.Trace.Tests
88
public class SpanTests
99
{
1010
private Mock<IDatadogTracer> _tracerMock;
11-
private Mock<ITraceContext> _traceContextMock;
11+
private TraceContext _traceContext;
1212

1313
public SpanTests()
1414
{
1515
_tracerMock = new Mock<IDatadogTracer>(MockBehavior.Strict);
16-
_traceContextMock = new Mock<ITraceContext>(MockBehavior.Strict);
17-
_traceContextMock.Setup(x => x.CloseSpan(It.IsAny<Span>()));
18-
_traceContextMock.Setup(x => x.GetCurrentSpanContext()).Returns<SpanContext>(null);
19-
_tracerMock.Setup(x => x.GetTraceContext()).Returns(_traceContextMock.Object);
16+
_traceContext = new TraceContext(_tracerMock.Object);
17+
_tracerMock.Setup(x => x.GetTraceContext()).Returns(_traceContext);
18+
_tracerMock.Setup(x => x.CloseCurrentTraceContext());
2019
_tracerMock.Setup(x => x.DefaultServiceName).Returns("DefaultServiceName");
2120
}
2221

@@ -30,7 +29,7 @@ public void SetTag_Tags_TagsAreProperlySet()
3029
span.SetTag("DoubleKey", 1.618);
3130
span.SetTag("BoolKey", true);
3231

33-
_traceContextMock.Verify(x => x.CloseSpan(It.IsAny<Span>()), Times.Never);
32+
_tracerMock.Verify(x => x.CloseCurrentTraceContext(), Times.Never);
3433
Assert.Equal("What's tracing", span.GetTag("StringKey"));
3534
Assert.Equal("42", span.GetTag("IntKey"));
3635
Assert.Equal("1.618", span.GetTag("DoubleKey"));
@@ -44,19 +43,20 @@ public void SetOperationName_ValidOperationName_OperationNameIsProperlySet()
4443

4544
span.SetOperationName("Op1");
4645

47-
_traceContextMock.Verify(x => x.CloseSpan(It.IsAny<Span>()), Times.Never);
46+
_tracerMock.Verify(x => x.CloseCurrentTraceContext(), Times.Never);
4847
Assert.Equal("Op1", span.OperationName);
4948
}
5049

5150
[Fact]
5251
public void Finish_StartTimeInThePastWithNoEndTime_DurationProperlyComputed()
5352
{
54-
var startTime = DateTimeOffset.UtcNow.AddMinutes(-1);
53+
// The 10 additional milliseconds account for the clock precision
54+
var startTime = DateTimeOffset.UtcNow.AddMinutes(-1).AddMilliseconds(-10);
5555
var span = new Span(_tracerMock.Object, null, null, null, startTime);
5656

5757
span.Finish();
5858

59-
_traceContextMock.Verify(x => x.CloseSpan(It.IsAny<Span>()), Times.Once);
59+
_tracerMock.Verify(x => x.CloseCurrentTraceContext(), Times.Once);
6060
Assert.True(span.Duration >= TimeSpan.FromMinutes(1) && span.Duration < TimeSpan.FromMinutes(2));
6161
}
6262

@@ -67,7 +67,7 @@ public async Task Finish_NoEndTimeProvided_SpanWriten()
6767
await Task.Delay(TimeSpan.FromMilliseconds(1));
6868
span.Finish();
6969

70-
_traceContextMock.Verify(x => x.CloseSpan(It.IsAny<Span>()), Times.Once);
70+
_tracerMock.Verify(x => x.CloseCurrentTraceContext(), Times.Once);
7171
Assert.True(span.Duration > TimeSpan.Zero);
7272
}
7373

@@ -80,7 +80,7 @@ public void Finish_EndTimeProvided_SpanWritenWithCorrectDuration()
8080

8181
span.Finish(endTime);
8282

83-
_traceContextMock.Verify(x => x.CloseSpan(It.IsAny<Span>()), Times.Once);
83+
_tracerMock.Verify(x => x.CloseCurrentTraceContext(), Times.Once);
8484
Assert.Equal(endTime - startTime, span.Duration);
8585
}
8686

@@ -93,7 +93,7 @@ public void Finish_EndTimeInThePast_DurationIs0()
9393

9494
span.Finish(endTime);
9595

96-
_traceContextMock.Verify(x => x.CloseSpan(It.IsAny<Span>()), Times.Once);
96+
_tracerMock.Verify(x => x.CloseCurrentTraceContext(), Times.Once);
9797
Assert.Equal(TimeSpan.Zero, span.Duration);
9898
}
9999

@@ -105,7 +105,7 @@ public void Dispose_ExitUsing_SpanWriten()
105105
{
106106
}
107107

108-
_traceContextMock.Verify(x => x.CloseSpan(It.IsAny<Span>()), Times.Once);
108+
_tracerMock.Verify(x => x.CloseCurrentTraceContext(), Times.Once);
109109
Assert.True(span.Duration > TimeSpan.Zero);
110110
}
111111
}

‎src/Datadog.Trace.Tests/TraceContextTests.cs‎

Lines changed: 37 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,37 @@
1+
using Moq;
2+
using System;
3+
using System.Collections.Generic;
4+
using System.Text;
5+
using Xunit;
6+
7+
namespace Datadog.Trace.Tests
8+
{
9+
public class TraceContextTests
10+
{
11+
private Mock<IDatadogTracer> _tracerMock = new Mock<IDatadogTracer>();
12+
13+
[Fact]
14+
public void UtcNow_GivesLegitTime()
15+
{
16+
var traceContext = new TraceContext(_tracerMock.Object);
17+
18+
var now = traceContext.UtcNow();
19+
var expectedNow = DateTimeOffset.UtcNow;
20+
21+
22+
Assert.True(expectedNow.Subtract(now) < TimeSpan.FromMilliseconds(30));
23+
}
24+
25+
[Fact]
26+
public void UtcNow_IsMonotonic()
27+
{
28+
var traceContext = new TraceContext(_tracerMock.Object);
29+
30+
var t1 = traceContext.UtcNow();
31+
var t2 = traceContext.UtcNow();
32+
33+
34+
Assert.True(t2.Subtract(t1) > TimeSpan.Zero);
35+
}
36+
}
37+
}

‎src/Datadog.Trace/ITraceContext.cs‎

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,6 @@
1-
namespace Datadog.Trace
1+
using System;
2+
3+
namespace Datadog.Trace
24
{
35
internal interface ITraceContext
46
{
@@ -9,5 +11,7 @@ internal interface ITraceContext
911
void CloseSpan(Span span);
1012

1113
SpanContext GetCurrentSpanContext();
14+
15+
DateTimeOffset UtcNow();
1216
}
1317
}

‎src/Datadog.Trace/Span.cs‎

Lines changed: 7 additions & 33 deletions
Original file line numberDiff line numberDiff line change
@@ -2,7 +2,6 @@
22
using OpenTracing;
33
using System;
44
using System.Collections.Generic;
5-
using System.Diagnostics;
65
using System.Text;
76

87
namespace Datadog.Trace
@@ -15,7 +14,6 @@ public class Span : ISpan
1514
private IDatadogTracer _tracer;
1615
private Dictionary<string, string> _tags;
1716
private SpanContext _context;
18-
private Stopwatch _sw;
1917

2018
ISpanContext ISpan.Context => _context;
2119

@@ -56,8 +54,7 @@ internal Span(IDatadogTracer tracer, SpanContext parent, string operationName, s
5654
}
5755
else
5856
{
59-
StartTime = DateTimeOffset.UtcNow;
60-
_sw = Stopwatch.StartNew();
57+
StartTime = _context.TraceContext.UtcNow();
6158
}
6259
}
6360

@@ -68,38 +65,15 @@ public void Dispose()
6865

6966
public void Finish()
7067
{
71-
// If the startTime was explicitely provided, we don't use a StopWatch to compute the duration
72-
if (_sw == null)
73-
{
74-
Finish(DateTimeOffset.UtcNow);
75-
return;
76-
}
77-
else
78-
{
79-
var shouldCloseSpan = false;
80-
lock (_lock)
81-
{
82-
ResourceName = ResourceName ?? OperationName;
83-
if (!IsFinished)
84-
{
85-
Duration = _sw.Elapsed;
86-
IsFinished = true;
87-
shouldCloseSpan = true;
88-
}
89-
}
90-
if (shouldCloseSpan)
91-
{
92-
_context.TraceContext.CloseSpan(this);
93-
}
94-
}
68+
Finish(_context.TraceContext.UtcNow());
9569
}
9670

9771
public void Finish(DateTimeOffset finishTimestamp)
9872
{
73+
var shouldCloseSpan = false;
9974
lock (_lock)
10075
{
10176
ResourceName = ResourceName ?? OperationName;
102-
var shouldCloseSpan = false;
10377
if (!IsFinished)
10478
{
10579
Duration = finishTimestamp - StartTime;
@@ -110,10 +84,10 @@ public void Finish(DateTimeOffset finishTimestamp)
11084
IsFinished = true;
11185
shouldCloseSpan = true;
11286
}
113-
if (shouldCloseSpan)
114-
{
115-
_context.TraceContext.CloseSpan(this);
116-
}
87+
}
88+
if (shouldCloseSpan)
89+
{
90+
_context.TraceContext.CloseSpan(this);
11791
}
11892
}
11993

‎src/Datadog.Trace/TraceContext.cs‎

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,7 @@
11
using Datadog.Trace.Logging;
2+
using System;
23
using System.Collections.Generic;
4+
using System.Diagnostics;
35
using System.Linq;
46

57
namespace Datadog.Trace
@@ -13,12 +15,21 @@ internal class TraceContext : ITraceContext
1315
private List<Span> _spans = new List<Span>();
1416
private int _openSpans = 0;
1517
private AsyncLocalCompat<SpanContext> _currentSpanContext = new AsyncLocalCompat<SpanContext>("Datadog.Trace.TraceContext._currentSpanContext");
18+
private DateTimeOffset _start;
19+
private Stopwatch _sw;
1620

1721
public bool Sampled { get; set; }
1822

1923
public TraceContext(IDatadogTracer tracer)
2024
{
2125
_tracer = tracer;
26+
_start = DateTimeOffset.UtcNow;
27+
_sw = Stopwatch.StartNew();
28+
}
29+
30+
public DateTimeOffset UtcNow()
31+
{
32+
return _start.Add(_sw.Elapsed);
2233
}
2334

2435
public SpanContext GetCurrentSpanContext()

0 commit comments

Comments
 (0)