Stop using EventIdHash to compare messages in telemetry logs #6526

andrewlock · 2025-01-10T12:28:49Z

Summary of changes

Compare the full log message and stack trace when determining uniqueness

Reason for change

We were using a computed hash value to compare two log messages for uniqueness. There's no good reason for that really, and we were getting some hash collisions which was causing flakiness in tests (and potentially, in real life). This should resolve the flakiness

Implementation details

Use a readonly record struct to hold both the message and the stack trace as the dictionary key.

Test coverage

Covered by existing tests

Other details

Would like to have used ValueTuple but we can't have nice things with .NET FX 4.6.1

andrewlock · 2025-01-10T13:03:48Z

Execution-Time Benchmarks Report ⏱️

Execution-time results for samples comparing the following branches/commits:

Execution-time benchmarks measure the whole time it takes to execute a program. And are intended to measure the one-off costs. Cases where the execution time results for the PR are worse than latest master results are shown in red. The following thresholds were used for comparing the execution times:

Welch test with statistical test for significance of 5%
Only results indicating a difference greater than 5% and 5 ms are considered.

Note that these results are based on a single point-in-time result for each branch. For full results, see the dashboard.

Graphs show the p99 interval based on the mean and StdDev of the test run, as well as the mean value of the run (shown as a diamond below the graph).

gantt
    title Execution time (ms) FakeDbCommand (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6526) - mean (69ms)  : 65, 72
     .   : milestone, 69,
    master - mean (69ms)  : 66, 71
     .   : milestone, 69,

    section CallTarget+Inlining+NGEN
    This PR (6526) - mean (978ms)  : 959, 998
     .   : milestone, 978,
    master - mean (981ms)  : 957, 1004
     .   : milestone, 981,

gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6526) - mean (108ms)  : 105, 110
     .   : milestone, 108,
    master - mean (108ms)  : 105, 111
     .   : milestone, 108,

    section CallTarget+Inlining+NGEN
    This PR (6526) - mean (678ms)  : 660, 695
     .   : milestone, 678,
    master - mean (678ms)  : 665, 692
     .   : milestone, 678,

gantt
    title Execution time (ms) FakeDbCommand (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6526) - mean (91ms)  : 89, 93
     .   : milestone, 91,
    master - mean (92ms)  : 90, 93
     .   : milestone, 92,

    section CallTarget+Inlining+NGEN
    This PR (6526) - mean (635ms)  : 620, 651
     .   : milestone, 635,
    master - mean (636ms)  : 620, 652
     .   : milestone, 636,

gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6526) - mean (194ms)  : 189, 198
     .   : milestone, 194,
    master - mean (194ms)  : 189, 198
     .   : milestone, 194,

    section CallTarget+Inlining+NGEN
    This PR (6526) - mean (1,102ms)  : 1070, 1134
     .   : milestone, 1102,
    master - mean (1,103ms)  : 1076, 1130
     .   : milestone, 1103,

gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6526) - mean (279ms)  : 274, 284
     .   : milestone, 279,
    master - mean (280ms)  : 276, 284
     .   : milestone, 280,

    section CallTarget+Inlining+NGEN
    This PR (6526) - mean (871ms)  : 848, 895
     .   : milestone, 871,
    master - mean (873ms)  : 849, 897
     .   : milestone, 873,

gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6526) - mean (267ms)  : 262, 271
     .   : milestone, 267,
    master - mean (269ms)  : 264, 273
     .   : milestone, 269,

    section CallTarget+Inlining+NGEN
    This PR (6526) - mean (852ms)  : 818, 885
     .   : milestone, 852,
    master - mean (856ms)  : 821, 890
     .   : milestone, 856,

datadog-ddstaging · 2025-01-10T13:05:19Z

Datadog Report

Branch report: andrew/fix-log-comparison
Commit report: ab9d293
Test service: dd-trace-dotnet

✅ 0 Failed, 236051 Passed, 2098 Skipped, 18h 54m 32.98s Total Time

andrewlock · 2025-01-10T13:47:27Z

Benchmarks Report for tracer 🐌

Benchmarks for #6526 compared to master:

1 benchmarks are slower, with geometric mean 1.131
All benchmarks have the same allocations

The following thresholds were used for comparing the benchmark speeds:

Mann–Whitney U test with statistical test for significance of 5%
Only results indicating a difference greater than 10% and 0.3 ns are considered.

Allocation changes below 0.5% are ignored.

Benchmark details

Benchmarks.Trace.ActivityBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Gen 2	Allocated
master	`StartStopWithChild`	net6.0	7.93μs	43.4ns	245ns	0.0163	0.00814	0	5.61 KB
master	`StartStopWithChild`	netcoreapp3.1	10.3μs	55.3ns	282ns	0.015	0.00499	0	5.8 KB
master	`StartStopWithChild`	net472	16.5μs	40ns	155ns	1.04	0.303	0.0982	6.21 KB
#6526	`StartStopWithChild`	net6.0	7.99μs	45ns	327ns	0.0196	0.00786	0	5.61 KB
#6526	`StartStopWithChild`	netcoreapp3.1	9.71μs	44.5ns	172ns	0.0237	0.00947	0	5.8 KB
#6526	`StartStopWithChild`	net472	16.7μs	77.5ns	372ns	1.04	0.3	0.1	6.2 KB

Benchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	485μs	426ns	1.65μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	646μs	2.23μs	10.7μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	net472	856μs	833ns	3.12μs	0.428	3.3 KB
#6526	`WriteAndFlushEnrichedTraces`	net6.0	477μs	239ns	927ns	0	2.7 KB
#6526	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	668μs	210ns	815ns	0	2.7 KB
#6526	`WriteAndFlushEnrichedTraces`	net472	853μs	374ns	1.45μs	0.422	3.3 KB

Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendRequest`	net6.0	157μs	1.39μs	13.6μs	0.154	14.47 KB
master	`SendRequest`	netcoreapp3.1	182μs	1.45μs	14μs	0.164	17.27 KB
master	`SendRequest`	net472	0.000357ns	0.000357ns	0.00129ns	0	0 b
#6526	`SendRequest`	net6.0	158μs	1.15μs	11.4μs	0.155	14.47 KB
#6526	`SendRequest`	netcoreapp3.1	173μs	1.07μs	10.6μs	0.161	17.27 KB
#6526	`SendRequest`	net472	0.0018ns	0.000832ns	0.00322ns	0	0 b

Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Gen 2	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	556μs	2.9μs	13.9μs	0.571	0	0	41.5 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	676μs	3.6μs	21.6μs	0.326	0	0	41.74 KB
master	`WriteAndFlushEnrichedTraces`	net472	880μs	3.71μs	14.4μs	8.36	2.64	0.44	53.28 KB
#6526	`WriteAndFlushEnrichedTraces`	net6.0	572μs	2.87μs	12.9μs	0.592	0	0	41.6 KB
#6526	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	665μs	3.48μs	19.1μs	0.331	0	0	41.9 KB
#6526	`WriteAndFlushEnrichedTraces`	net472	838μs	3.65μs	14.2μs	8.22	2.47	0.411	53.34 KB

Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`ExecuteNonQuery`	net6.0	1.34μs	1.21ns	4.68ns	0.0145	0	1.02 KB
master	`ExecuteNonQuery`	netcoreapp3.1	1.89μs	2.27ns	8.77ns	0.0131	0	1.02 KB
master	`ExecuteNonQuery`	net472	2.07μs	2.15ns	8.33ns	0.156	0.00104	987 B
#6526	`ExecuteNonQuery`	net6.0	1.32μs	1.49ns	5.75ns	0.0146	0	1.02 KB
#6526	`ExecuteNonQuery`	netcoreapp3.1	1.82μs	1.76ns	6.58ns	0.0136	0	1.02 KB
#6526	`ExecuteNonQuery`	net472	2.02μs	2.03ns	7.84ns	0.156	0.00101	987 B

Benchmarks.Trace.ElasticsearchBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #6526

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.ElasticsearchBenchmark.CallElasticsearch‑net6.0	1.131	1,136.63	1,285.71

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`CallElasticsearch`	net6.0	1.14μs	0.4ns	1.44ns	0.0134	976 B
master	`CallElasticsearch`	netcoreapp3.1	1.61μs	0.622ns	2.24ns	0.0129	976 B
master	`CallElasticsearch`	net472	2.57μs	1.3ns	5.03ns	0.157	995 B
master	`CallElasticsearchAsync`	net6.0	1.33μs	0.593ns	2.3ns	0.0133	952 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.7μs	0.43ns	1.55ns	0.0135	1.02 KB
master	`CallElasticsearchAsync`	net472	2.64μs	11.1ns	54.6ns	0.167	1.05 KB
#6526	`CallElasticsearch`	net6.0	1.29μs	0.602ns	2.25ns	0.0137	976 B
#6526	`CallElasticsearch`	netcoreapp3.1	1.53μs	0.785ns	3.04ns	0.0129	976 B
#6526	`CallElasticsearch`	net472	2.61μs	2.64ns	10.2ns	0.158	995 B
#6526	`CallElasticsearchAsync`	net6.0	1.28μs	0.562ns	2.1ns	0.0134	952 B
#6526	`CallElasticsearchAsync`	netcoreapp3.1	1.58μs	0.858ns	3.21ns	0.0142	1.02 KB
#6526	`CallElasticsearchAsync`	net472	2.53μs	1.09ns	4.08ns	0.166	1.05 KB

Benchmarks.Trace.GraphQLBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`ExecuteAsync`	net6.0	1.28μs	0.552ns	2.14ns	0.0134	952 B
master	`ExecuteAsync`	netcoreapp3.1	1.69μs	1.86ns	7.2ns	0.0126	952 B
master	`ExecuteAsync`	net472	1.8μs	0.676ns	2.44ns	0.145	915 B
#6526	`ExecuteAsync`	net6.0	1.34μs	0.602ns	2.17ns	0.0131	952 B
#6526	`ExecuteAsync`	netcoreapp3.1	1.54μs	0.529ns	1.98ns	0.0131	952 B
#6526	`ExecuteAsync`	net472	1.85μs	0.48ns	1.73ns	0.144	915 B

Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendAsync`	net6.0	4.44μs	1.55ns	5.58ns	0.031	2.31 KB
master	`SendAsync`	netcoreapp3.1	5.36μs	2.33ns	9.03ns	0.0377	2.85 KB
master	`SendAsync`	net472	7.39μs	2.11ns	8.16ns	0.494	3.12 KB
#6526	`SendAsync`	net6.0	4.48μs	1.63ns	5.88ns	0.0313	2.31 KB
#6526	`SendAsync`	netcoreapp3.1	5.18μs	1.61ns	5.8ns	0.0363	2.85 KB
#6526	`SendAsync`	net472	7.39μs	1.6ns	6.18ns	0.496	3.12 KB

Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	1.49μs	0.747ns	2.8ns	0.0232	1.64 KB
master	`EnrichedLog`	netcoreapp3.1	2.18μs	0.9ns	3.37ns	0.0221	1.64 KB
master	`EnrichedLog`	net472	2.79μs	1.77ns	6.61ns	0.249	1.57 KB
#6526	`EnrichedLog`	net6.0	1.45μs	0.739ns	2.86ns	0.0234	1.64 KB
#6526	`EnrichedLog`	netcoreapp3.1	2.31μs	1.86ns	6.95ns	0.0221	1.64 KB
#6526	`EnrichedLog`	net472	2.68μs	1.12ns	4.18ns	0.249	1.57 KB

Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`EnrichedLog`	net6.0	116μs	132ns	511ns	0	0	4.28 KB
master	`EnrichedLog`	netcoreapp3.1	121μs	267ns	1.03μs	0	0	4.28 KB
master	`EnrichedLog`	net472	153μs	141ns	544ns	0.686	0.229	4.46 KB
#6526	`EnrichedLog`	net6.0	118μs	201ns	777ns	0.06	0	4.28 KB
#6526	`EnrichedLog`	netcoreapp3.1	122μs	275ns	1.06μs	0	0	4.28 KB
#6526	`EnrichedLog`	net472	150μs	100ns	388ns	0.676	0.225	4.46 KB

Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	3.06μs	0.964ns	3.73ns	0.0307	2.2 KB
master	`EnrichedLog`	netcoreapp3.1	4.17μs	2.2ns	8.52ns	0.0294	2.2 KB
master	`EnrichedLog`	net472	4.84μs	1.78ns	6.89ns	0.319	2.02 KB
#6526	`EnrichedLog`	net6.0	2.99μs	0.993ns	3.84ns	0.0298	2.2 KB
#6526	`EnrichedLog`	netcoreapp3.1	4.09μs	0.995ns	3.72ns	0.0286	2.2 KB
#6526	`EnrichedLog`	net472	4.86μs	1.17ns	4.53ns	0.32	2.02 KB

Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendReceive`	net6.0	1.29μs	0.909ns	3.52ns	0.0162	1.14 KB
master	`SendReceive`	netcoreapp3.1	1.73μs	1.11ns	4.29ns	0.0148	1.14 KB
master	`SendReceive`	net472	2.18μs	1.52ns	5.7ns	0.183	1.16 KB
#6526	`SendReceive`	net6.0	1.32μs	0.698ns	2.7ns	0.016	1.14 KB
#6526	`SendReceive`	netcoreapp3.1	1.89μs	1.05ns	3.93ns	0.0159	1.14 KB
#6526	`SendReceive`	net472	2.09μs	1.26ns	4.72ns	0.183	1.16 KB

Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	2.7μs	3.08ns	11.9ns	0.0229	1.6 KB
master	`EnrichedLog`	netcoreapp3.1	3.9μs	2.94ns	11.4ns	0.0214	1.65 KB
master	`EnrichedLog`	net472	4.33μs	1.85ns	6.67ns	0.322	2.04 KB
#6526	`EnrichedLog`	net6.0	2.7μs	0.911ns	3.41ns	0.0216	1.6 KB
#6526	`EnrichedLog`	netcoreapp3.1	3.85μs	1.34ns	5.03ns	0.021	1.65 KB
#6526	`EnrichedLog`	net472	4.3μs	1.74ns	6.28ns	0.322	2.04 KB

Benchmarks.Trace.SpanBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net6.0	404ns	0.152ns	0.59ns	0.00821	576 B
master	`StartFinishSpan`	netcoreapp3.1	551ns	0.399ns	1.54ns	0.00772	576 B
master	`StartFinishSpan`	net472	689ns	0.628ns	2.43ns	0.0917	578 B
master	`StartFinishScope`	net6.0	486ns	0.386ns	1.44ns	0.00982	696 B
master	`StartFinishScope`	netcoreapp3.1	717ns	0.597ns	2.31ns	0.00934	696 B
master	`StartFinishScope`	net472	869ns	0.342ns	1.32ns	0.104	658 B
#6526	`StartFinishSpan`	net6.0	423ns	0.578ns	2.24ns	0.00812	576 B
#6526	`StartFinishSpan`	netcoreapp3.1	569ns	0.153ns	0.571ns	0.00787	576 B
#6526	`StartFinishSpan`	net472	649ns	0.214ns	0.827ns	0.0918	578 B
#6526	`StartFinishScope`	net6.0	499ns	0.192ns	0.718ns	0.00975	696 B
#6526	`StartFinishScope`	netcoreapp3.1	685ns	0.405ns	1.57ns	0.00935	696 B
#6526	`StartFinishScope`	net472	904ns	0.313ns	1.21ns	0.104	658 B

Benchmarks.Trace.TraceAnnotationsBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`RunOnMethodBegin`	net6.0	653ns	0.406ns	1.57ns	0.00984	696 B
master	`RunOnMethodBegin`	netcoreapp3.1	996ns	0.69ns	2.67ns	0.00903	696 B
master	`RunOnMethodBegin`	net472	1.05μs	0.725ns	2.71ns	0.105	658 B
#6526	`RunOnMethodBegin`	net6.0	663ns	0.406ns	1.57ns	0.00997	696 B
#6526	`RunOnMethodBegin`	netcoreapp3.1	946ns	0.67ns	2.6ns	0.00953	696 B
#6526	`RunOnMethodBegin`	net472	1.13μs	0.807ns	3.13ns	0.104	658 B

Stop using EventIdHash to compare messages

ab9d293

andrewlock added type:bug area:telemetry labels Jan 10, 2025

andrewlock requested a review from a team as a code owner January 10, 2025 12:28

github-actions bot added the area:tracer The core tracer library (Datadog.Trace, does not include OpenTracing, native code, or integrations) label Jan 10, 2025

kevingosse approved these changes Jan 10, 2025

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Stop using EventIdHash to compare messages in telemetry logs #6526

Stop using EventIdHash to compare messages in telemetry logs #6526

andrewlock commented Jan 10, 2025

andrewlock commented Jan 10, 2025

datadog-ddstaging bot commented Jan 10, 2025 •

edited

Loading

andrewlock commented Jan 10, 2025

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #6526

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Stop using EventIdHash to compare messages in telemetry logs #6526

Are you sure you want to change the base?

Stop using EventIdHash to compare messages in telemetry logs #6526

Conversation

andrewlock commented Jan 10, 2025

Summary of changes

Reason for change

Implementation details

Test coverage

Other details

andrewlock commented Jan 10, 2025

Execution-Time Benchmarks Report ⏱️

datadog-ddstaging bot commented Jan 10, 2025 • edited Loading

Datadog Report

andrewlock commented Jan 10, 2025

Benchmarks Report for tracer 🐌

Benchmark details

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #6526

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

datadog-ddstaging bot commented Jan 10, 2025 •

edited

Loading