Log header warnings only once #4369

kevingosse · 2023-07-06T13:35:08Z

Summary of changes

ParseUtility.ParseXxx methods log a warning when the parsing fails. However, those methods can be called multiple times per request, so in some situations the amount of logs can be excessive.

This PR changes the logic to log as a warning the first time, then as debug the next times.

Reason for change

One customer escalations that shown evidence of significant contention around that log.

andrewlock

This also plays into work @tonyredondo was looking into - turning on buffering before flushing, which would also likely resolve this. That said, downgrading the log I guess is ok, though it means if you miss the first one, you're not going to know about this until a restart... :/

datadog-ddstaging · 2023-07-06T14:04:55Z

Datadog Report

Branch report: kevin/log_limit
Commit report: cb55ed4

❄️ dd-trace-dotnet: 0 Failed, 2 New Flaky, 290888 Passed, 1026 Skipped, 35m 59.77s Wall Time

New Flaky Tests (2)

CheckGitMetataFromBinary - Datadog.Profiler.IntegrationTests.DebugInfo.GitMetadataTest - Last Failure
Expand for error
```
 Exit code of "catchsegv" should be 0 instead of 134 (= 0x86)
 Expected: True
 Actual:   False
```

CheckProfilesSentThroughNamedPipe - Datadog.Profiler.IntegrationTests.WindowsOnly.NamedPipeTestcs - Last Failure

Expand for error

 Found error message in the log file D:\a\1\s\profiler\build_data\TestApplication_Samples.Computer012f22a03d_3728\net7.0\logs\DD-DotNet-Profiler-Native-Samples.Computer01-4064.log
 Expected: False
 Actual:   True

kevingosse · 2023-07-06T14:20:05Z

That said, downgrading the log I guess is ok, though it means if you miss the first one, you're not going to know about this until a restart... :/

True. But I feel like we ask to enable debug logging whenever there's an issue about spans anyway.

andrewlock · 2023-07-06T14:28:30Z

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 (4369) - mean (3,019ms)  : 2942, 3097
     .   : milestone, 3019,
    master - mean (3,029ms)  : 2936, 3122
     .   : milestone, 3029,

    section CallTarget+Inlining+NGEN
    This PR (4369) - mean (3,829ms)  : 3730, 3928
     .   : milestone, 3829,
    master - mean (3,819ms)  : 3744, 3895
     .   : milestone, 3819,

gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4369) - mean (3,117ms)  : 3024, 3209
     .   : milestone, 3117,
    master - mean (3,144ms)  : 3009, 3280
     .   : milestone, 3144,

    section CallTarget+Inlining+NGEN
    This PR (4369) - mean (3,625ms)  : 3558, 3691
     .   : milestone, 3625,
    master - mean (3,649ms)  : 3549, 3750
     .   : milestone, 3649,

gantt
    title Execution time (ms) FakeDbCommand (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4369) - mean (3,122ms)  : 3006, 3239
     .   : milestone, 3122,
    master - mean (3,107ms)  : 2972, 3241
     .   : milestone, 3107,

    section CallTarget+Inlining+NGEN
    This PR (4369) - mean (3,588ms)  : 3525, 3652
     .   : milestone, 3588,
    master - mean (3,604ms)  : 3534, 3675
     .   : milestone, 3604,

gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4369) - mean (191ms)  : 187, 196
     .   : milestone, 191,
    master - mean (191ms)  : 187, 196
     .   : milestone, 191,

    section CallTarget+Inlining+NGEN
    This PR (4369) - mean (1,109ms)  : 1077, 1140
     .   : milestone, 1109,
    master - mean (1,114ms)  : 1088, 1140
     .   : milestone, 1114,

gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4369) - mean (372ms)  : 365, 380
     .   : milestone, 372,
    master - mean (373ms)  : 367, 379
     .   : milestone, 373,

    section CallTarget+Inlining+NGEN
    This PR (4369) - mean (1,165ms)  : 1139, 1190
     .   : milestone, 1165,
    master - mean (1,169ms)  : 1143, 1195
     .   : milestone, 1169,

gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4369) - mean (360ms)  : 356, 364
     .   : milestone, 360,
    master - mean (362ms)  : 354, 371
     .   : milestone, 362,

    section CallTarget+Inlining+NGEN
    This PR (4369) - mean (1,126ms)  : 1105, 1146
     .   : milestone, 1126,
    master - mean (1,128ms)  : 1102, 1154
     .   : milestone, 1128,

andrewlock · 2023-07-06T14:42:08Z

Benchmarks Report 🐌

Benchmarks for #4369 compared to master:

1 benchmarks are faster, with geometric mean 1.147
3 benchmarks are slower, with geometric mean 1.259
1 benchmarks have fewer 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.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	473μs	294ns	1.14μs	0	2.62 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	632μs	91ns	328ns	0	2.63 KB
master	`WriteAndFlushEnrichedTraces`	net472	802μs	375ns	1.4μs	0.403	3.22 KB
#4369	`WriteAndFlushEnrichedTraces`	net6.0	471μs	257ns	995ns	0	2.62 KB
#4369	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	625μs	618ns	2.39μs	0	2.62 KB
#4369	`WriteAndFlushEnrichedTraces`	net472	790μs	486ns	1.82μs	0.396	3.22 KB

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

Slower ⚠️ in #4369

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.AppSecBodyBenchmark.ObjectExtractorSimpleBody‑net6.0	1.541	120.66	185.92

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`AllCycleSimpleBody`	net6.0	38.4μs	21.1ns	81.8ns	0.0192	0	1.65 KB
master	`AllCycleSimpleBody`	netcoreapp3.1	40.9μs	118ns	456ns	0.0206	0	1.63 KB
master	`AllCycleSimpleBody`	net472	41.2μs	11.8ns	42.5ns	0.267	0	1.69 KB
master	`AllCycleMoreComplexBody`	net6.0	221μs	207ns	803ns	0.111	0	9.22 KB
master	`AllCycleMoreComplexBody`	netcoreapp3.1	229μs	99.6ns	373ns	0.114	0	9.12 KB
master	`AllCycleMoreComplexBody`	net472	238μs	88.9ns	321ns	1.42	0	9.28 KB
master	`ObjectExtractorSimpleBody`	net6.0	121ns	0.0296ns	0.107ns	0.00392	0	280 B
master	`ObjectExtractorSimpleBody`	netcoreapp3.1	177ns	0.0661ns	0.238ns	0.00371	0	272 B
master	`ObjectExtractorSimpleBody`	net472	148ns	0.0758ns	0.284ns	0.0446	0	281 B
master	`ObjectExtractorMoreComplexBody`	net6.0	2.94μs	1.43ns	5.55ns	0.0545	0	3.88 KB
master	`ObjectExtractorMoreComplexBody`	netcoreapp3.1	4.09μs	2.45ns	9.47ns	0.051	0	3.78 KB
master	`ObjectExtractorMoreComplexBody`	net472	4.23μs	3.68ns	14.2ns	0.618	0.00632	3.89 KB
#4369	`AllCycleSimpleBody`	net6.0	38.5μs	15.7ns	58.7ns	0.0193	0	1.65 KB
#4369	`AllCycleSimpleBody`	netcoreapp3.1	40.1μs	95.2ns	369ns	0.0207	0	1.63 KB
#4369	`AllCycleSimpleBody`	net472	41.4μs	8.99ns	34.8ns	0.247	0	1.69 KB
#4369	`AllCycleMoreComplexBody`	net6.0	220μs	157ns	607ns	0.11	0	9.22 KB
#4369	`AllCycleMoreComplexBody`	netcoreapp3.1	230μs	141ns	529ns	0	0	9.12 KB
#4369	`AllCycleMoreComplexBody`	net472	239μs	119ns	443ns	1.43	0	9.28 KB
#4369	`ObjectExtractorSimpleBody`	net6.0	186ns	0.0505ns	0.196ns	0.00394	0	280 B
#4369	`ObjectExtractorSimpleBody`	netcoreapp3.1	172ns	0.0962ns	0.36ns	0.00373	0	272 B
#4369	`ObjectExtractorSimpleBody`	net472	145ns	0.101ns	0.392ns	0.0446	0	281 B
#4369	`ObjectExtractorMoreComplexBody`	net6.0	3.05μs	6.99ns	27.1ns	0.0543	0	3.88 KB
#4369	`ObjectExtractorMoreComplexBody`	netcoreapp3.1	4.19μs	1.93ns	7.48ns	0.0524	0	3.78 KB
#4369	`ObjectExtractorMoreComplexBody`	net472	4.15μs	1.63ns	6.32ns	0.617	0.00621	3.89 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendRequest`	net6.0	169μs	244ns	944ns	0.253	18.03 KB
master	`SendRequest`	netcoreapp3.1	188μs	381ns	1.48μs	0.186	20.09 KB
master	`SendRequest`	net472	0ns	0ns	0ns	0	0 b
#4369	`SendRequest`	net6.0	168μs	76.4ns	296ns	0.17	18.03 KB
#4369	`SendRequest`	netcoreapp3.1	190μs	137ns	495ns	0.191	20.09 KB
#4369	`SendRequest`	net472	0ns	0ns	0ns	0	0 b

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

Fewer allocations 🎉 in #4369

Benchmark	Base Allocated	Diff Allocated	Change	Change %
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark.WriteAndFlushEnrichedTraces‑netcoreapp3.1	41.87 KB	41.59 KB	-283 B	-0.68%

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Gen 2	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	520μs	1.19μs	4.6μs	0.539	0	0	41.39 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	634μs	2.27μs	8.8μs	0.312	0	0	41.87 KB
master	`WriteAndFlushEnrichedTraces`	net472	788μs	2.71μs	10.5μs	8.1	2.31	0.386	53.26 KB
#4369	`WriteAndFlushEnrichedTraces`	net6.0	512μs	592ns	2.22μs	0.508	0	0	41.48 KB
#4369	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	634μs	1.53μs	5.94μs	0.311	0	0	41.59 KB
#4369	`WriteAndFlushEnrichedTraces`	net472	782μs	3.08μs	11.9μs	8.15	2.33	0.388	53.23 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	924ns	0.367ns	1.42ns	0.00978	0	720 B
master	`ExecuteNonQuery`	netcoreapp3.1	1.18μs	0.5ns	1.87ns	0.00949	0	720 B
master	`ExecuteNonQuery`	net472	1.4μs	0.707ns	2.74ns	0.108	0.000699	682 B
#4369	`ExecuteNonQuery`	net6.0	880ns	0.287ns	1.11ns	0.0101	0	720 B
#4369	`ExecuteNonQuery`	netcoreapp3.1	1.17μs	0.712ns	2.76ns	0.00997	0	720 B
#4369	`ExecuteNonQuery`	net472	1.41μs	0.628ns	2.43ns	0.108	0	682 B

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

Slower ⚠️ in #4369

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.ElasticsearchBenchmark.CallElasticsearchAsync‑net6.0	1.158	1,013.10	1,173.28

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`CallElasticsearch`	net6.0	1.07μs	0.502ns	1.95ns	0.0134	0	944 B
master	`CallElasticsearch`	netcoreapp3.1	1.24μs	0.63ns	2.44ns	0.0124	0	944 B
master	`CallElasticsearch`	net472	1.95μs	0.775ns	2.9ns	0.151	0.000975	955 B
master	`CallElasticsearchAsync`	net6.0	1.01μs	0.391ns	1.51ns	0.0127	0	920 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.36μs	0.593ns	2.14ns	0.0129	0	992 B
master	`CallElasticsearchAsync`	net472	2.15μs	0.586ns	2.27ns	0.16	0.00108	1.01 KB
#4369	`CallElasticsearch`	net6.0	1.07μs	0.51ns	1.98ns	0.0133	0	944 B
#4369	`CallElasticsearch`	netcoreapp3.1	1.18μs	0.42ns	1.51ns	0.0126	0	944 B
#4369	`CallElasticsearch`	net472	2.1μs	0.662ns	2.56ns	0.151	0.00105	955 B
#4369	`CallElasticsearchAsync`	net6.0	1.17μs	0.31ns	1.2ns	0.013	0	920 B
#4369	`CallElasticsearchAsync`	netcoreapp3.1	1.36μs	0.459ns	1.72ns	0.0137	0	992 B
#4369	`CallElasticsearchAsync`	net472	2.05μs	0.719ns	2.78ns	0.16	0.00103	1.01 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`ExecuteAsync`	net6.0	1.06μs	0.414ns	1.6ns	0.0129	0	912 B
master	`ExecuteAsync`	netcoreapp3.1	1.39μs	0.965ns	3.74ns	0.0125	0	912 B
master	`ExecuteAsync`	net472	1.52μs	0.745ns	2.79ns	0.139	0.000762	875 B
#4369	`ExecuteAsync`	net6.0	1.06μs	0.462ns	1.79ns	0.0131	0	912 B
#4369	`ExecuteAsync`	netcoreapp3.1	1.36μs	2.17ns	8.4ns	0.0119	0	912 B
#4369	`ExecuteAsync`	net472	1.57μs	0.626ns	2.43ns	0.138	0.000782	875 B

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendAsync`	net6.0	3.66μs	1.19ns	4.61ns	0.0255	1.9 KB
master	`SendAsync`	netcoreapp3.1	4.2μs	1.74ns	6.5ns	0.0336	2.43 KB
master	`SendAsync`	net472	6.91μs	9.02ns	31.3ns	0.476	3 KB
#4369	`SendAsync`	net6.0	3.62μs	1.15ns	4.31ns	0.0254	1.9 KB
#4369	`SendAsync`	netcoreapp3.1	4.22μs	1.76ns	6.83ns	0.0316	2.43 KB
#4369	`SendAsync`	net472	7.02μs	2.52ns	9.42ns	0.475	3 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	1.35μs	0.58ns	2.25ns	0.0224	1.62 KB
master	`EnrichedLog`	netcoreapp3.1	2.12μs	0.622ns	2.24ns	0.0221	1.62 KB
master	`EnrichedLog`	net472	2.4μs	2.5ns	9.67ns	0.244	1.54 KB
#4369	`EnrichedLog`	net6.0	1.29μs	0.855ns	3.31ns	0.0224	1.62 KB
#4369	`EnrichedLog`	netcoreapp3.1	1.95μs	0.913ns	3.42ns	0.0226	1.62 KB
#4369	`EnrichedLog`	net472	2.36μs	2.11ns	8.19ns	0.244	1.54 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	112μs	195ns	756ns	0.0556	0	4.21 KB
master	`EnrichedLog`	netcoreapp3.1	118μs	313ns	1.17μs	0	0	4.21 KB
master	`EnrichedLog`	net472	149μs	196ns	759ns	0.668	0.223	4.38 KB
#4369	`EnrichedLog`	net6.0	110μs	137ns	532ns	0.055	0	4.21 KB
#4369	`EnrichedLog`	netcoreapp3.1	116μs	129ns	466ns	0.0577	0	4.21 KB
#4369	`EnrichedLog`	net472	148μs	163ns	589ns	0.663	0.221	4.38 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`EnrichedLog`	net6.0	3.06μs	1.1ns	4.27ns	0.0525	0	3.71 KB
master	`EnrichedLog`	netcoreapp3.1	3.97μs	1.62ns	6.28ns	0.0496	0	3.69 KB
master	`EnrichedLog`	net472	4.84μs	2.09ns	8.09ns	0.526	0.00241	3.31 KB
#4369	`EnrichedLog`	net6.0	3.18μs	1.35ns	5.24ns	0.0516	0	3.71 KB
#4369	`EnrichedLog`	netcoreapp3.1	3.83μs	1.67ns	6.47ns	0.0498	0	3.69 KB
#4369	`EnrichedLog`	net472	4.73μs	1.4ns	5.42ns	0.526	0.00236	3.31 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendReceive`	net6.0	1.23μs	0.768ns	2.87ns	0.0154	1.11 KB
master	`SendReceive`	netcoreapp3.1	1.48μs	0.56ns	2.09ns	0.0148	1.11 KB
master	`SendReceive`	net472	1.66μs	2.23ns	8.62ns	0.177	1.12 KB
#4369	`SendReceive`	net6.0	1.21μs	0.406ns	1.52ns	0.0158	1.11 KB
#4369	`SendReceive`	netcoreapp3.1	1.46μs	0.48ns	1.73ns	0.0152	1.11 KB
#4369	`SendReceive`	net472	1.76μs	1.33ns	4.96ns	0.177	1.12 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	2.52μs	0.552ns	1.99ns	0.0214	1.53 KB
master	`EnrichedLog`	netcoreapp3.1	3.7μs	2.25ns	8.43ns	0.0204	1.58 KB
master	`EnrichedLog`	net472	4.08μs	1.24ns	4.65ns	0.311	1.96 KB
#4369	`EnrichedLog`	net6.0	2.53μs	0.668ns	2.59ns	0.0215	1.53 KB
#4369	`EnrichedLog`	netcoreapp3.1	3.58μs	5.33ns	20.6ns	0.0213	1.58 KB
#4369	`EnrichedLog`	net472	4.12μs	1.64ns	6.15ns	0.311	1.96 KB

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

Slower ⚠️ in #4369

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0	1.118	479.72	536.10

Faster 🎉 in #4369

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0	1.147	437.55	381.40

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net6.0	438ns	0.103ns	0.384ns	0.00757	536 B
master	`StartFinishSpan`	netcoreapp3.1	573ns	0.281ns	1.09ns	0.00738	536 B
master	`StartFinishSpan`	net472	619ns	0.185ns	0.694ns	0.0852	538 B
master	`StartFinishScope`	net6.0	480ns	0.248ns	0.962ns	0.00923	656 B
master	`StartFinishScope`	netcoreapp3.1	665ns	0.162ns	0.605ns	0.00865	656 B
master	`StartFinishScope`	net472	843ns	0.261ns	1.01ns	0.0981	618 B
#4369	`StartFinishSpan`	net6.0	381ns	0.123ns	0.46ns	0.00741	536 B
#4369	`StartFinishSpan`	netcoreapp3.1	528ns	0.197ns	0.736ns	0.00716	536 B
#4369	`StartFinishSpan`	net472	652ns	0.188ns	0.703ns	0.0854	538 B
#4369	`StartFinishScope`	net6.0	536ns	0.143ns	0.517ns	0.00919	656 B
#4369	`StartFinishScope`	netcoreapp3.1	702ns	0.302ns	1.17ns	0.0089	656 B
#4369	`StartFinishScope`	net472	863ns	0.547ns	2.12ns	0.0982	618 B

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`RunOnMethodBegin`	net6.0	569ns	0.118ns	0.44ns	0.00903	656 B
master	`RunOnMethodBegin`	netcoreapp3.1	844ns	1.47ns	5.7ns	0.00879	656 B
master	`RunOnMethodBegin`	net472	925ns	0.204ns	0.788ns	0.0979	618 B
#4369	`RunOnMethodBegin`	net6.0	552ns	0.143ns	0.533ns	0.00929	656 B
#4369	`RunOnMethodBegin`	netcoreapp3.1	797ns	0.413ns	1.43ns	0.00874	656 B
#4369	`RunOnMethodBegin`	net472	922ns	0.392ns	1.52ns	0.0981	618 B

andrewlock · 2023-07-06T16:33:29Z

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 (4369) (10.576M)   : 0, 10575500
    master (10.965M)   : 0, 10965224
    benchmarks/2.33.0 (11.213M)   : 0, 11212993
    benchmarks/2.9.0 (11.118M)   : 0, 11117516

    section Automatic
    This PR (4369) (7.665M)   : 0, 7664781
    master (7.722M)   : 0, 7721646
    benchmarks/2.33.0 (7.578M)   : 0, 7577833
    benchmarks/2.9.0 (8.218M)   : 0, 8217621

    section Trace stats
    master (7.739M)   : 0, 7739490
    benchmarks/2.33.0 (7.586M)   : 0, 7586413

    section Manual
    This PR (4369) (9.908M)   : 0, 9907648
    master (9.899M)   : 0, 9899120
    benchmarks/2.33.0 (10.050M)   : 0, 10049682

    section Manual + Automatic
    This PR (4369) (7.480M)   : 0, 7480464
    master (7.342M)   : 0, 7341595
    benchmarks/2.33.0 (7.461M)   : 0, 7461071

    section Version Conflict
    master (6.595M)   : 0, 6594841
    benchmarks/2.33.0 (6.706M)   : 0, 6705768

gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (4369) (9.656M)   : 0, 9655963
    benchmarks/2.33.0 (9.854M)   : 0, 9854380
    benchmarks/2.9.0 (9.560M)   : 0, 9560344

    section Automatic
    This PR (4369) (6.772M)   : 0, 6771811
    benchmarks/2.33.0 (6.781M)   : 0, 6781408

    section Trace stats
    benchmarks/2.33.0 (6.876M)   : 0, 6875549

    section Manual
    This PR (4369) (8.377M)   : 0, 8377228
    benchmarks/2.33.0 (8.659M)   : 0, 8658618

    section Manual + Automatic
    This PR (4369) (6.536M)   : 0, 6536103
    benchmarks/2.33.0 (6.364M)   : 0, 6364163

    section Version Conflict
    benchmarks/2.33.0 (5.865M)   : 0, 5865173

gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (4369) (10.718M)   : 0, 10718339
    master (10.670M)   : 0, 10669660
    benchmarks/2.33.0 (10.579M)   : 0, 10578933
    benchmarks/2.9.0 (10.207M)   : 0, 10206911

    section Automatic
    This PR (4369) (7.740M)   : 0, 7740309
    master (7.678M)   : 0, 7678235
    benchmarks/2.33.0 (7.457M)   : 0, 7457212
    benchmarks/2.9.0 (7.491M)   : 0, 7491408

    section Trace stats
    master (7.749M)   : 0, 7749241
    benchmarks/2.33.0 (7.471M)   : 0, 7470661

    section Manual
    This PR (4369) (9.477M)   : 0, 9476963
    master (9.796M)   : 0, 9796376
    benchmarks/2.33.0 (9.168M)   : 0, 9167980

    section Manual + Automatic
    This PR (4369) (7.399M)   : 0, 7398850
    master (7.630M)   : 0, 7630036
    benchmarks/2.33.0 (7.048M)   : 0, 7048019

    section Version Conflict
    master (6.809M)   : 0, 6808904
    benchmarks/2.33.0 (6.484M)   : 0, 6483597

gantt
    title Throughput Linux x64 (ASM) (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (4369) (7.787M)   : 0, 7787406
    master (7.837M)   : 0, 7836680
    benchmarks/2.33.0 (7.894M)   : 0, 7894351
    benchmarks/2.9.0 (8.085M)   : 0, 8085159

    section No attack
    This PR (4369) (2.224M)   : 0, 2224494
    master (2.211M)   : 0, 2211112
    benchmarks/2.33.0 (2.233M)   : 0, 2232790
    benchmarks/2.9.0 (3.354M)   : 0, 3353571

    section Attack
    This PR (4369) (1.904M)   : 0, 1904153
    master (1.905M)   : 0, 1904607
    benchmarks/2.33.0 (1.937M)   : 0, 1937400
    benchmarks/2.9.0 (2.567M)   : 0, 2566556

    section Blocking
    This PR (4369) (3.853M)   : 0, 3852538
    master (3.858M)   : 0, 3858134
    benchmarks/2.33.0 (3.859M)   : 0, 3859464

Log header warnings only once

cb55ed4

kevingosse requested a review from a team as a code owner July 6, 2023 13:35

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

andrewlock approved these changes Jul 6, 2023

View reviewed changes

bouwkast approved these changes Jul 6, 2023

View reviewed changes

kevingosse merged commit a820f5e into master Jul 7, 2023

kevingosse deleted the kevin/log_limit branch July 7, 2023 10:45

github-actions bot added this to the vNext milestone Jul 7, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Log header warnings only once #4369

Log header warnings only once #4369

kevingosse commented Jul 6, 2023

andrewlock left a comment

datadog-ddstaging bot commented Jul 6, 2023 •

edited

Loading

kevingosse commented Jul 6, 2023

andrewlock commented Jul 6, 2023

andrewlock commented Jul 6, 2023

Raw results

Slower ⚠️ in #4369

Raw results

Raw results

Fewer allocations 🎉 in #4369

Raw results

Raw results

Slower ⚠️ in #4369

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #4369

Faster 🎉 in #4369

Raw results

Raw results

andrewlock commented Jul 6, 2023

Log header warnings only once #4369

Log header warnings only once #4369

Conversation

kevingosse commented Jul 6, 2023

Summary of changes

Reason for change

andrewlock left a comment

Choose a reason for hiding this comment

datadog-ddstaging bot commented Jul 6, 2023 • edited Loading

Datadog Report

New Flaky Tests (2)

kevingosse commented Jul 6, 2023

andrewlock commented Jul 6, 2023

Execution-Time Benchmarks Report ⏱️

andrewlock commented Jul 6, 2023

Benchmarks Report 🐌

Benchmark details

Raw results

Slower ⚠️ in #4369

Raw results

Raw results

Fewer allocations 🎉 in #4369

Raw results

Raw results

Slower ⚠️ in #4369

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #4369

Faster 🎉 in #4369

Raw results

Raw results

andrewlock commented Jul 6, 2023

Throughput/Crank Report:zap:

datadog-ddstaging bot commented Jul 6, 2023 •

edited

Loading