-
Notifications
You must be signed in to change notification settings - Fork 140
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Use TraceId128
in log instead of TraceId
#5312
Conversation
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:
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 (5312) - mean (73ms) : 65, 82
. : milestone, 73,
master - mean (73ms) : 65, 82
. : milestone, 73,
section CallTarget+Inlining+NGEN
This PR (5312) - mean (1,006ms) : 986, 1026
. : milestone, 1006,
master - mean (1,005ms) : 978, 1033
. : milestone, 1005,
gantt
title Execution time (ms) FakeDbCommand (.NET Core 3.1)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (5312) - mean (110ms) : 106, 114
. : milestone, 110,
master - mean (111ms) : 108, 114
. : milestone, 111,
section CallTarget+Inlining+NGEN
This PR (5312) - mean (723ms) : 701, 745
. : milestone, 723,
master - mean (733ms) : 711, 754
. : milestone, 733,
gantt
title Execution time (ms) FakeDbCommand (.NET 6)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (5312) - mean (94ms) : 91, 96
. : milestone, 94,
master - mean (93ms) : 91, 96
. : milestone, 93,
section CallTarget+Inlining+NGEN
This PR (5312) - mean (676ms) : 658, 693
. : milestone, 676,
master - mean (683ms) : 665, 702
. : milestone, 683,
gantt
title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (5312) - mean (188ms) : 184, 191
. : milestone, 188,
master - mean (187ms) : 185, 190
. : milestone, 187,
section CallTarget+Inlining+NGEN
This PR (5312) - mean (1,078ms) : 1054, 1103
. : milestone, 1078,
master - mean (1,079ms) : 1060, 1099
. : milestone, 1079,
gantt
title Execution time (ms) HttpMessageHandler (.NET Core 3.1)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (5312) - mean (272ms) : 267, 276
. : milestone, 272,
master - mean (271ms) : 267, 275
. : milestone, 271,
section CallTarget+Inlining+NGEN
This PR (5312) - mean (882ms) : 861, 903
. : milestone, 882,
master - mean (883ms) : 861, 904
. : milestone, 883,
gantt
title Execution time (ms) HttpMessageHandler (.NET 6)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (5312) - mean (261ms) : 257, 264
. : milestone, 261,
master - mean (260ms) : 256, 264
. : milestone, 260,
section CallTarget+Inlining+NGEN
This PR (5312) - mean (868ms) : 842, 894
. : milestone, 868,
master - mean (861ms) : 841, 882
. : milestone, 861,
|
Datadog ReportBranch report: ✅ 0 Failed, 327900 Passed, 1586 Skipped, 35m 17.21s Wall Time |
Benchmarks Report for tracer 🐌Benchmarks for #5312 compared to master:
The following thresholds were used for comparing the benchmark speeds:
Allocation changes below 0.5% are ignored. Benchmark detailsBenchmarks.Trace.ActivityBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.GraphQLBenchmark - Slower
|
Benchmark | diff/base | Base Median (ns) | Diff Median (ns) | Modality |
---|---|---|---|---|
Benchmarks.Trace.GraphQLBenchmark.ExecuteAsync‑net6.0 | 1.148 | 1,224.99 | 1,406.36 |
Raw results
Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
---|---|---|---|---|---|---|---|---|---|
master | ExecuteAsync |
net6.0 | 1.22μs | 1.26ns | 4.88ns | 0.0127 | 0 | 0 | 928 B |
master | ExecuteAsync |
netcoreapp3.1 | 1.69μs | 0.938ns | 3.63ns | 0.0125 | 0 | 0 | 928 B |
master | ExecuteAsync |
net472 | 1.9μs | 1.86ns | 7.21ns | 0.141 | 0 | 0 | 891 B |
#5312 | ExecuteAsync |
net6.0 | 1.41μs | 0.832ns | 3.22ns | 0.0126 | 0 | 0 | 928 B |
#5312 | ExecuteAsync |
netcoreapp3.1 | 1.74μs | 0.803ns | 3.01ns | 0.0121 | 0 | 0 | 928 B |
#5312 | ExecuteAsync |
net472 | 1.9μs | 1.22ns | 4.55ns | 0.141 | 0 | 0 | 891 B |
Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️
Raw results
Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
---|---|---|---|---|---|---|---|---|---|
master | SendAsync |
net6.0 | 4.18μs | 2.03ns | 7.59ns | 0.0293 | 0 | 0 | 2.16 KB |
master | SendAsync |
netcoreapp3.1 | 5.08μs | 2.91ns | 10.9ns | 0.0356 | 0 | 0 | 2.7 KB |
master | SendAsync |
net472 | 7.79μs | 8.2ns | 31.8ns | 0.533 | 0 | 0 | 3.38 KB |
#5312 | SendAsync |
net6.0 | 4.29μs | 2.64ns | 9.88ns | 0.0302 | 0 | 0 | 2.16 KB |
#5312 | SendAsync |
netcoreapp3.1 | 5.24μs | 1.87ns | 6.76ns | 0.0367 | 0 | 0 | 2.7 KB |
#5312 | SendAsync |
net472 | 7.72μs | 5.22ns | 19.5ns | 0.536 | 0 | 0 | 3.38 KB |
Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️
Raw results
Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
---|---|---|---|---|---|---|---|---|---|
master | EnrichedLog |
net6.0 | 1.45μs | 0.629ns | 2.35ns | 0.0231 | 0 | 0 | 1.65 KB |
master | EnrichedLog |
netcoreapp3.1 | 2.11μs | 0.959ns | 3.71ns | 0.0221 | 0 | 0 | 1.65 KB |
master | EnrichedLog |
net472 | 2.54μs | 1.16ns | 4.34ns | 0.25 | 0 | 0 | 1.57 KB |
#5312 | EnrichedLog |
net6.0 | 1.43μs | 0.745ns | 2.89ns | 0.0231 | 0 | 0 | 1.65 KB |
#5312 | EnrichedLog |
netcoreapp3.1 | 2.24μs | 1.11ns | 4.17ns | 0.0215 | 0 | 0 | 1.65 KB |
#5312 | EnrichedLog |
net472 | 2.67μs | 3.12ns | 12.1ns | 0.249 | 0 | 0 | 1.57 KB |
Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️
Raw results
Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
---|---|---|---|---|---|---|---|---|---|
master | EnrichedLog |
net6.0 | 113μs | 197ns | 763ns | 0 | 0 | 0 | 4.23 KB |
master | EnrichedLog |
netcoreapp3.1 | 118μs | 102ns | 381ns | 0.0592 | 0 | 0 | 4.23 KB |
master | EnrichedLog |
net472 | 145μs | 92.8ns | 360ns | 0.654 | 0.218 | 0 | 4.41 KB |
#5312 | EnrichedLog |
net6.0 | 112μs | 89.4ns | 346ns | 0.0567 | 0 | 0 | 4.23 KB |
#5312 | EnrichedLog |
netcoreapp3.1 | 118μs | 166ns | 643ns | 0.0592 | 0 | 0 | 4.23 KB |
#5312 | EnrichedLog |
net472 | 146μs | 103ns | 387ns | 0.66 | 0.22 | 0 | 4.41 KB |
Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️
Raw results
Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
---|---|---|---|---|---|---|---|---|---|
master | EnrichedLog |
net6.0 | 3μs | 1.16ns | 4.03ns | 0.0303 | 0 | 0 | 2.21 KB |
master | EnrichedLog |
netcoreapp3.1 | 4.28μs | 2.4ns | 8.97ns | 0.0298 | 0 | 0 | 2.21 KB |
master | EnrichedLog |
net472 | 4.84μs | 2.15ns | 8.06ns | 0.321 | 0 | 0 | 2.02 KB |
#5312 | EnrichedLog |
net6.0 | 3.12μs | 1.06ns | 3.82ns | 0.0313 | 0 | 0 | 2.21 KB |
#5312 | EnrichedLog |
netcoreapp3.1 | 4.33μs | 1.55ns | 5.79ns | 0.028 | 0 | 0 | 2.21 KB |
#5312 | EnrichedLog |
net472 | 4.89μs | 1.95ns | 7.28ns | 0.32 | 0 | 0 | 2.02 KB |
Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️
Raw results
Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
---|---|---|---|---|---|---|---|---|---|
master | SendReceive |
net6.0 | 1.41μs | 0.571ns | 2.21ns | 0.0162 | 0 | 0 | 1.18 KB |
master | SendReceive |
netcoreapp3.1 | 1.87μs | 1.14ns | 4.27ns | 0.0159 | 0 | 0 | 1.18 KB |
master | SendReceive |
net472 | 2.3μs | 1ns | 3.89ns | 0.187 | 0 | 0 | 1.18 KB |
#5312 | SendReceive |
net6.0 | 1.39μs | 1.12ns | 4.17ns | 0.0167 | 0 | 0 | 1.18 KB |
#5312 | SendReceive |
netcoreapp3.1 | 1.81μs | 0.748ns | 2.8ns | 0.0154 | 0 | 0 | 1.18 KB |
#5312 | SendReceive |
net472 | 2.25μs | 2.58ns | 10ns | 0.187 | 0 | 0 | 1.18 KB |
Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️
Raw results
Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
---|---|---|---|---|---|---|---|---|---|
master | EnrichedLog |
net6.0 | 2.69μs | 0.905ns | 3.39ns | 0.0215 | 0 | 0 | 1.55 KB |
master | EnrichedLog |
netcoreapp3.1 | 3.9μs | 1ns | 3.89ns | 0.0213 | 0 | 0 | 1.6 KB |
master | EnrichedLog |
net472 | 4.43μs | 2.12ns | 8.23ns | 0.315 | 0 | 0 | 1.99 KB |
#5312 | EnrichedLog |
net6.0 | 2.74μs | 0.914ns | 3.42ns | 0.0223 | 0 | 0 | 1.55 KB |
#5312 | EnrichedLog |
netcoreapp3.1 | 3.95μs | 1.16ns | 4.17ns | 0.0217 | 0 | 0 | 1.6 KB |
#5312 | EnrichedLog |
net472 | 4.38μs | 2.24ns | 8.38ns | 0.315 | 0 | 0 | 1.99 KB |
Benchmarks.Trace.SpanBenchmark - Slower ⚠️ Same allocations ✔️
Slower ⚠️ in #5312
Benchmark
diff/base
Base Median (ns)
Diff Median (ns)
Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0
1.143
451.45
515.82
Faster 🎉 in #5312
Benchmark
base/diff
Base Median (ns)
Diff Median (ns)
Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0
1.119
599.73
536.07
Benchmark | diff/base | Base Median (ns) | Diff Median (ns) | Modality |
---|---|---|---|---|
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0 | 1.143 | 451.45 | 515.82 |
Benchmark | base/diff | Base Median (ns) | Diff Median (ns) | Modality |
---|---|---|---|---|
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0 | 1.119 | 599.73 | 536.07 |
Raw results
Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
---|---|---|---|---|---|---|---|---|---|
master | StartFinishSpan |
net6.0 | 451ns | 0.527ns | 1.97ns | 0.00771 | 0 | 0 | 552 B |
master | StartFinishSpan |
netcoreapp3.1 | 682ns | 1.07ns | 4.15ns | 0.00736 | 0 | 0 | 552 B |
master | StartFinishSpan |
net472 | 730ns | 0.393ns | 1.52ns | 0.0877 | 0 | 0 | 554 B |
master | StartFinishScope |
net6.0 | 600ns | 0.714ns | 2.67ns | 0.00952 | 0 | 0 | 672 B |
master | StartFinishScope |
netcoreapp3.1 | 813ns | 1.04ns | 4.04ns | 0.0089 | 0 | 0 | 672 B |
master | StartFinishScope |
net472 | 1.01μs | 1.03ns | 3.86ns | 0.1 | 0 | 0 | 634 B |
#5312 | StartFinishSpan |
net6.0 | 517ns | 0.996ns | 3.86ns | 0.00762 | 0 | 0 | 552 B |
#5312 | StartFinishSpan |
netcoreapp3.1 | 736ns | 1.93ns | 7.47ns | 0.00774 | 0 | 0 | 552 B |
#5312 | StartFinishSpan |
net472 | 799ns | 1.71ns | 6.64ns | 0.0878 | 0 | 0 | 554 B |
#5312 | StartFinishScope |
net6.0 | 535ns | 1.06ns | 4.11ns | 0.00938 | 0 | 0 | 672 B |
#5312 | StartFinishScope |
netcoreapp3.1 | 871ns | 1.17ns | 4.51ns | 0.00909 | 0 | 0 | 672 B |
#5312 | StartFinishScope |
net472 | 950ns | 1.68ns | 6.52ns | 0.101 | 0 | 0 | 634 B |
Benchmarks.Trace.TraceAnnotationsBenchmark - Faster 🎉 Same allocations ✔️
Faster 🎉 in #5312
Benchmark
base/diff
Base Median (ns)
Diff Median (ns)
Modality
Benchmarks.Trace.TraceAnnotationsBenchmark.RunOnMethodBegin‑net6.0
1.172
700.47
597.43
Benchmark | base/diff | Base Median (ns) | Diff Median (ns) | Modality |
---|---|---|---|---|
Benchmarks.Trace.TraceAnnotationsBenchmark.RunOnMethodBegin‑net6.0 | 1.172 | 700.47 | 597.43 |
Raw results
Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
---|---|---|---|---|---|---|---|---|---|
master | RunOnMethodBegin |
net6.0 | 700ns | 0.762ns | 2.95ns | 0.00944 | 0 | 0 | 672 B |
master | RunOnMethodBegin |
netcoreapp3.1 | 993ns | 1.81ns | 7.01ns | 0.00908 | 0 | 0 | 672 B |
master | RunOnMethodBegin |
net472 | 1.09μs | 1.73ns | 6.72ns | 0.101 | 0 | 0 | 634 B |
#5312 | RunOnMethodBegin |
net6.0 | 596ns | 0.94ns | 3.64ns | 0.00946 | 0 | 0 | 672 B |
#5312 | RunOnMethodBegin |
netcoreapp3.1 | 928ns | 1.24ns | 4.8ns | 0.00898 | 0 | 0 | 672 B |
#5312 | RunOnMethodBegin |
net472 | 1.02μs | 2.59ns | 10ns | 0.101 | 0 | 0 | 634 B |
Throughput/Crank Report:zap:Throughput results for AspNetCoreSimpleController comparing the following branches/commits: Cases where throughput results for the PR are worse than latest master (5% drop or greater), results are shown in red. Note that these results are based on a single point-in-time result for each branch. For full results, see one of the many, many dashboards! gantt
title Throughput Linux x64 (Total requests)
dateFormat X
axisFormat %s
section Baseline
This PR (5312) (11.066M) : 0, 11066406
master (11.199M) : 0, 11199038
benchmarks/2.9.0 (11.199M) : 0, 11198849
section Automatic
This PR (5312) (7.501M) : 0, 7501313
master (7.662M) : 0, 7662012
benchmarks/2.9.0 (8.073M) : 0, 8073104
section Trace stats
This PR (5312) (7.888M) : 0, 7887954
master (8.205M) : 0, 8205275
section Manual
This PR (5312) (9.540M) : 0, 9540410
master (9.883M) : 0, 9883344
section Manual + Automatic
This PR (5312) (7.171M) : 0, 7170552
master (7.295M) : 0, 7295083
section Version Conflict
This PR (5312) (6.503M) : 0, 6503277
master (6.628M) : 0, 6627687
gantt
title Throughput Linux arm64 (Total requests)
dateFormat X
axisFormat %s
section Baseline
This PR (5312) (9.518M) : 0, 9518058
master (9.627M) : 0, 9626775
benchmarks/2.9.0 (9.424M) : 0, 9424414
section Automatic
This PR (5312) (6.629M) : 0, 6629360
master (6.666M) : 0, 6665718
section Trace stats
This PR (5312) (6.916M) : 0, 6916475
master (6.927M) : 0, 6927005
section Manual
This PR (5312) (8.224M) : 0, 8223827
master (8.376M) : 0, 8375804
section Manual + Automatic
This PR (5312) (6.219M) : 0, 6219097
master (6.218M) : 0, 6217652
section Version Conflict
This PR (5312) (5.640M) : 0, 5640115
master (5.680M) : 0, 5679994
gantt
title Throughput Windows x64 (Total requests)
dateFormat X
axisFormat %s
section Baseline
This PR (5312) (10.083M) : 0, 10082712
master (9.866M) : 0, 9865815
benchmarks/2.9.0 (9.559M) : 0, 9558711
section Automatic
This PR (5312) (7.017M) : 0, 7016872
master (6.996M) : 0, 6995543
benchmarks/2.9.0 (7.049M) : 0, 7049098
section Trace stats
This PR (5312) (7.378M) : 0, 7377594
master (7.364M) : 0, 7364144
section Manual
This PR (5312) (8.775M) : 0, 8774525
master (8.631M) : 0, 8631324
section Manual + Automatic
This PR (5312) (6.710M) : 0, 6709819
master (6.707M) : 0, 6707173
section Version Conflict
This PR (5312) (6.132M) : 0, 6132094
master (6.201M) : 0, 6201222
|
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
LGTM
Summary of changes
Use
TraceId128
in log instead ofTraceId
when recording exceptionReason for change
TraceId
only gives the 64-bit TraceId,TraceId128
gives the full thingImplementation details
TraceId
->TraceId128
Test coverage
meh
Other details
Originally done in
SetExceptionTags()
throws #5291And flagged by @lucaspimentel here