Skip to content

Commit f3b5b46

Browse files
dd-calebdd-caleb
authored
attempt to fix flakiness in redis tests (#142)
* poll for spans * sort spans * maybe fix flakiness * better logging * allow out of order spans * try sync version * abstract out task handling for spans and make it deterministic * fix webapi example
1 parent 6bea3f7 commit f3b5b46

File tree

13 files changed

+222
-128
lines changed

13 files changed

+222
-128
lines changed

‎samples/Samples.RedisCore/Program.cs‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -74,11 +74,11 @@ private static void RunStackExchange(string prefix)
7474

7575
RunCommands(new TupleList<string, Func<object>>
7676
{
77-
{ "PING", () => db.Ping() },
77+
{ "PING", () => db.PingAsync().Result },
7878
{ "DDCUSTOM", () => db.Execute("DDCUSTOM", "COMMAND") },
7979
{ "ECHO", () => db.Execute("ECHO", "Hello World") },
8080
{ "SLOWLOG", () => db.Execute("SLOWLOG", "GET") },
81-
{ "INCR", () => db.StringIncrementAsync($"{prefix}INCR").Result },
81+
{ "INCR", () => db.StringIncrement($"{prefix}INCR") },
8282
{ "INCR", () => db.StringIncrement($"{prefix}INCR", 1.25) },
8383
{ "TIME", () => db.Execute("TIME") },
8484
});

‎src/Datadog.Trace.ClrProfiler.Managed/DynamicMethodBuilder.cs‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -79,6 +79,11 @@ public static TDelegate CreateMethodCallDelegate<TDelegate>(
7979
}).ToArray();
8080
}
8181

82+
if (methodGenericArguments != null)
83+
{
84+
methods = methods.Where(m => m.IsGenericMethodDefinition).ToArray();
85+
}
86+
8287
MethodInfo methodInfo = methods.FirstOrDefault();
8388
if (methodInfo == null)
8489
{

‎src/Datadog.Trace.ClrProfiler.Managed/Extensions.cs‎

Lines changed: 125 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,125 @@
1+
using System;
2+
using System.Collections.Concurrent;
3+
using System.Collections.Generic;
4+
using System.Linq;
5+
using System.Text;
6+
using System.Threading.Tasks;
7+
8+
namespace Datadog.Trace.ClrProfiler
9+
{
10+
/// <summary>
11+
/// Extension methods
12+
/// </summary>
13+
public static class Extensions
14+
{
15+
private static ConcurrentDictionary<Type, Func<Span, Task, Action<Exception>, Task>> _traceTaskMethods = new ConcurrentDictionary<Type, Func<Span, Task, Action<Exception>, Task>>();
16+
17+
/// <summary>
18+
/// Trace traces a function which returns an object with the given span. If the object is a task, the span will be finished when the task completes.
19+
/// </summary>
20+
/// <param name="span">The span to use for tracing. The scope for the span should not be set to finish on close.</param>
21+
/// <param name="func">The function to trace</param>
22+
/// <param name="onComplete">an optional function to call when the function/task completes. By default exceptions will be added to the span and the span will be finished.</param>
23+
/// <returns>The result of the function call</returns>
24+
public static object Trace(this Span span, Func<object> func, Action<Exception> onComplete = null)
25+
{
26+
onComplete = onComplete ?? new Action<Exception>(e =>
27+
{
28+
if (e != null)
29+
{
30+
span.SetException(e);
31+
}
32+
span.Finish();
33+
});
34+
35+
try
36+
{
37+
var result = func();
38+
39+
if (result is Task task)
40+
{
41+
var typ = task.GetType();
42+
var genericArgs = GetGenericTypeArguments(typeof(Task<>), typ);
43+
if (genericArgs.Length == 1)
44+
{
45+
if (!_traceTaskMethods.TryGetValue(genericArgs[0], out var traceTask))
46+
{
47+
traceTask = DynamicMethodBuilder.CreateMethodCallDelegate<Func<Span, Task, Action<Exception>, Task>>(typeof(Extensions), "TraceTask", methodGenericArguments: genericArgs);
48+
_traceTaskMethods[genericArgs[0]] = traceTask;
49+
}
50+
51+
result = traceTask(span, task, onComplete);
52+
}
53+
else
54+
{
55+
result = TraceTask(span, task, onComplete);
56+
}
57+
}
58+
else
59+
{
60+
onComplete(null);
61+
}
62+
63+
return result;
64+
}
65+
catch (Exception e)
66+
{
67+
onComplete(e);
68+
throw;
69+
}
70+
}
71+
72+
private static Task TraceTask(Span span, Task task, Action<Exception> onComplete)
73+
{
74+
return task.ContinueWith(t =>
75+
{
76+
if (t.IsFaulted)
77+
{
78+
onComplete(t.Exception);
79+
throw t.Exception;
80+
}
81+
82+
if (t.IsCompleted)
83+
{
84+
onComplete(null);
85+
}
86+
});
87+
}
88+
89+
private static Task<T> TraceTask<T>(Span span, Task<T> task, Action<Exception> onComplete)
90+
{
91+
return task.ContinueWith(t =>
92+
{
93+
if (t.IsFaulted)
94+
{
95+
onComplete(t.Exception);
96+
throw t.Exception;
97+
}
98+
99+
if (t.IsCompleted)
100+
{
101+
onComplete(null);
102+
return t.Result;
103+
}
104+
105+
return default;
106+
});
107+
}
108+
109+
private static Type[] GetGenericTypeArguments(Type generic, Type toCheck)
110+
{
111+
while (toCheck != null && toCheck != typeof(object))
112+
{
113+
var cur = toCheck.IsGenericType ? toCheck.GetGenericTypeDefinition() : toCheck;
114+
if (generic == cur)
115+
{
116+
return toCheck.GetGenericArguments();
117+
}
118+
119+
toCheck = toCheck.BaseType;
120+
}
121+
122+
return null;
123+
}
124+
}
125+
}

‎src/Datadog.Trace.ClrProfiler.Managed/Integrations/AspNetWebApi2Integration.cs‎

Lines changed: 12 additions & 39 deletions
Original file line numberDiff line numberDiff line change
@@ -24,49 +24,22 @@ public static class AspNetWebApi2Integration
2424
/// <returns>A task with the result</returns>
2525
public static dynamic ExecuteAsync(dynamic @this, dynamic controllerContext, dynamic cancellationTokenSource)
2626
{
27-
dynamic result;
28-
29-
using (var scope = CreateScope(controllerContext))
27+
using (Scope scope = CreateScope(controllerContext))
3028
{
31-
try
32-
{
33-
result = @this.ExecuteAsync(controllerContext, ((CancellationTokenSource)cancellationTokenSource).Token);
34-
if (result is Task task)
35-
{
36-
task.ContinueWith(
37-
t =>
38-
{
39-
if (t.IsFaulted)
40-
{
41-
scope.Span.SetException(t.Exception);
42-
scope.Span.Finish();
43-
}
44-
else if (t.IsCanceled)
45-
{
46-
// abandon the span
47-
}
48-
else
49-
{
50-
// some fields aren't set till after execution, so repopulate anything missing
51-
UpdateSpan(controllerContext, scope.Span);
52-
scope.Span.Finish();
53-
}
54-
});
55-
}
56-
else
29+
return scope.Span.Trace(
30+
() => @this.ExecuteAsync(controllerContext, ((CancellationTokenSource)cancellationTokenSource).Token),
31+
onComplete: e =>
5732
{
33+
if (e != null)
34+
{
35+
scope.Span.SetException(e);
36+
}
37+
38+
// some fields aren't set till after execution, so repopulate anything missing
39+
UpdateSpan(controllerContext, scope.Span);
5840
scope.Span.Finish();
59-
}
60-
}
61-
catch (Exception ex)
62-
{
63-
scope.Span.SetException(ex);
64-
scope.Span.Finish();
65-
throw;
66-
}
41+
});
6742
}
68-
69-
return result;
7043
}
7144

7245
private static Scope CreateScope(dynamic controllerContext)

‎src/Datadog.Trace.ClrProfiler.Managed/Integrations/StackExchangeRedis.cs‎

Lines changed: 1 addition & 42 deletions
Original file line numberDiff line numberDiff line change
@@ -1,12 +1,5 @@
11
using System;
22
using System.Collections.Concurrent;
3-
using System.Collections.Generic;
4-
using System.IO;
5-
using System.Linq;
6-
using System.Linq.Expressions;
7-
using System.Reflection;
8-
using System.Text;
9-
using System.Threading.Tasks;
103

114
namespace Datadog.Trace.ClrProfiler.Integrations
125
{
@@ -89,41 +82,7 @@ public static object ExecuteAsyncImpl(object multiplexer, object message, object
8982

9083
using (var scope = CreateScope(multiplexer, message, server, finishOnClose: false))
9184
{
92-
try
93-
{
94-
var result = originalMethod(multiplexer, message, processor, state, server);
95-
if (result is Task task)
96-
{
97-
task.ContinueWith(t =>
98-
{
99-
if (t.IsFaulted)
100-
{
101-
scope.Span.SetException(t.Exception);
102-
scope.Span.Finish();
103-
}
104-
else if (t.IsCanceled)
105-
{
106-
// abandon the span
107-
}
108-
else
109-
{
110-
scope.Span.Finish();
111-
}
112-
});
113-
}
114-
else
115-
{
116-
scope.Span.Finish();
117-
}
118-
119-
return result;
120-
}
121-
catch (Exception ex)
122-
{
123-
scope.Span.SetException(ex);
124-
scope.Span.Finish();
125-
throw;
126-
}
85+
return scope.Span.Trace(() => originalMethod(multiplexer, message, processor, state, server));
12786
}
12887
}
12988

‎src/Datadog.Trace/TraceContext.cs‎

Lines changed: 3 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
using System;
1+
using System;
22
using System.Collections.Generic;
33
using System.Diagnostics;
44
using System.Linq;
@@ -43,25 +43,9 @@ public void CloseSpan(Span span)
4343
lock (_lock)
4444
{
4545
_openSpans--;
46-
if (span.IsRootSpan)
46+
if (_openSpans == 0)
4747
{
48-
if (_openSpans != 0)
49-
{
50-
_log.DebugFormat("Some child spans were not finished before the root. {NumberOfOpenSpans}", _openSpans);
51-
if (_tracer.IsDebugEnabled)
52-
{
53-
foreach (var s in _spans.Where(x => !x.IsFinished))
54-
{
55-
_log.DebugFormat("Span {UnfinishedSpan} was not finished before its root span", s);
56-
}
57-
58-
// TODO:bertrand Instead detect if we are being garbage collected and warn at that point
59-
}
60-
}
61-
else
62-
{
63-
_tracer.Write(_spans);
64-
}
48+
_tracer.Write(_spans);
6549
}
6650
}
6751
}

‎test/Datadog.Trace.ClrProfiler.IntegrationTests/AspNetMvc5Tests.cs‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -54,8 +54,7 @@ public void SubmitsTraces()
5454
}
5555
}
5656

57-
var spans = agent.GetSpans();
58-
57+
var spans = agent.WaitForSpans(1);
5958
Assert.True(spans.Count > 0, "expected at least one span");
6059
foreach (var span in spans)
6160
{

‎test/Datadog.Trace.ClrProfiler.IntegrationTests/ServiceStackRedisTests.cs‎

Lines changed: 4 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -28,8 +28,7 @@ public void SubmitsTraces()
2828
{
2929
Assert.True(processResult.ExitCode >= 0, $"Process exited with code {processResult.ExitCode}");
3030

31-
var spans = agent.GetSpans().Where(s => s.Type == "redis").ToList();
32-
Assert.Equal(11, spans.Count);
31+
var spans = agent.WaitForSpans(11).Where(s => s.Type == "redis").OrderBy(s => s.Start).ToList();
3332

3433
foreach (var span in spans)
3534
{
@@ -58,10 +57,10 @@ public void SubmitsTraces()
5857
for (int i = 0; i < expected.Count; i++)
5958
{
6059
var e1 = expected[i].Item1;
61-
var a1 = spans[i].Resource;
62-
6360
var e2 = expected[i].Item2;
64-
var a2 = spans[i].Tags.Get<string>("redis.raw_command");
61+
62+
var a1 = i < spans.Count ? spans[i].Resource : string.Empty;
63+
var a2 = i < spans.Count ? spans[i].Tags.Get<string>("redis.raw_command") : string.Empty;
6564

6665
Assert.True(e1 == a1, $"invalid resource name for span {i}, {e1} != {a1}");
6766
Assert.True(e2 == a2, $"invalid raw command for span {i}, {e2} != {a2}");

‎test/Datadog.Trace.ClrProfiler.IntegrationTests/SqlServerTests.cs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -25,7 +25,7 @@ public void SubmitsTraces()
2525
{
2626
Assert.True(processResult.ExitCode >= 0, $"Process exited with code {processResult.ExitCode}");
2727

28-
var spans = agent.GetSpans();
28+
var spans = agent.WaitForSpans(1);
2929
Assert.True(spans.Count > 0, "expected at least one span");
3030
foreach (var span in spans)
3131
{

‎test/Datadog.Trace.ClrProfiler.IntegrationTests/StackExchangeRedisTests.cs‎

Lines changed: 4 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -24,8 +24,7 @@ public void SubmitsTraces()
2424
{
2525
Assert.True(processResult.ExitCode >= 0, $"Process exited with code {processResult.ExitCode}");
2626

27-
var spans = agent.GetSpans().Where(s => s.Type == "redis").ToList();
28-
Assert.Equal(8, spans.Count);
27+
var spans = agent.WaitForSpans(8).Where(s => s.Type == "redis").OrderBy(s => s.Start).ToList();
2928

3029
foreach (var span in spans)
3130
{
@@ -51,10 +50,10 @@ public void SubmitsTraces()
5150
for (int i = 0; i < expected.Count; i++)
5251
{
5352
var e1 = expected[i].Item1;
54-
var a1 = spans[i].Resource;
55-
5653
var e2 = expected[i].Item2;
57-
var a2 = spans[i].Tags.Get<string>("redis.raw_command");
54+
55+
var a1 = i < spans.Count ? spans[i].Resource : string.Empty;
56+
var a2 = i < spans.Count ? spans[i].Tags.Get<string>("redis.raw_command") : string.Empty;
5857

5958
Assert.True(e1 == a1, $"invalid resource name for span {i}, {e1} != {a1}");
6059
Assert.True(e2 == a2, $"invalid raw command for span {i}, {e2} != {a2}");

0 commit comments

Comments
 (0)