Display the crash tests stdout live #5964

kevingosse · 2024-08-30T09:33:36Z

Summary of changes

In the crashtracking installer smoke-tests, display the output as it comes instead of all at once when it finishes.

Reason for change

The job sometimes hangs. When it happens, it gets killed after the timeout elapses, and we see no output because the command didn't complete.

Implementation details

Bash.

datadog-ddstaging · 2024-08-30T09:51:21Z

Datadog Report

Branch report: kevin/smoke_test_output
Commit report: fb0d876
Test service: dd-trace-dotnet

❌ 1 Failed (0 Known Flaky), 360557 Passed, 2061 Skipped, 14h 40m 36.05s Total Time

❌ Failed Tests (1)

Profiler_liveheap - scenarios - Details

Expand for error

 
 Fatal error. 0xC0000005
    at System.Diagnostics.Tracing.EventPipePayloadDecoder.DecodePayload(EventMetadata ByRef, System.ReadOnlySpan\`1<Byte>)
    at System.Diagnostics.Tracing.EventPipeEventDispatcher.DispatchEventsToEventListeners()
    at System.Threading.Tasks.Task.InnerInvoke()
    at System.Threading.Tasks.Task+<>c.<.cctor>b__273_0(System.Object)
    at System.Threading.ExecutionContexm <any number to pass to the scenario - used for contention duration for example>] [--timeout <duration in seconds> | --run-infinitely]uteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread)
    at System.Threading.Tasks.Task.ExecuteEntryUnsafe(System.Threading.Thread)
    at System.Threading.Tasks.ThreadPoolTaskScheduler+<>c.<.cctor>b__10_0(System.Object)
    at System.Threading.Thread.StartCallback()
 ...

andrewlock · 2024-08-30T09:56:13Z

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).

andrewlock · 2024-08-30T10:27:24Z

Benchmarks Report for tracer 🐌

Benchmarks for #5964 compared to master:

2 benchmarks are slower, with geometric mean 1.135
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.69μs	43.2ns	280ns	0.0157	0.00784	0	5.42 KB
master	`StartStopWithChild`	netcoreapp3.1	10.2μs	53.9ns	280ns	0.0193	0.00965	0	5.62 KB
master	`StartStopWithChild`	net472	16μs	35.8ns	134ns	1.02	0.303	0.0957	6.07 KB
#5964	`StartStopWithChild`	net6.0	7.74μs	43.7ns	306ns	0.0186	0.00742	0	5.43 KB
#5964	`StartStopWithChild`	netcoreapp3.1	9.72μs	55ns	401ns	0.0193	0.00964	0	5.62 KB
#5964	`StartStopWithChild`	net472	15.9μs	32.2ns	125ns	1.03	0.325	0.0952	6.08 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	483μs	289ns	1.08μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	632μs	438ns	1.7μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	net472	855μs	438ns	1.64μs	0.425	3.3 KB
#5964	`WriteAndFlushEnrichedTraces`	net6.0	487μs	336ns	1.21μs	0	2.7 KB
#5964	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	630μs	262ns	1.02μs	0	2.7 KB
#5964	`WriteAndFlushEnrichedTraces`	net472	849μs	747ns	2.89μs	0.425	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	184μs	936ns	5.13μs	0.184	18.45 KB
master	`SendRequest`	netcoreapp3.1	209μs	1.06μs	8.1μs	0.197	20.61 KB
master	`SendRequest`	net472	0.00272ns	0.000763ns	0.00295ns	0	0 b
#5964	`SendRequest`	net6.0	188μs	1.01μs	5.24μs	0.18	18.45 KB
#5964	`SendRequest`	netcoreapp3.1	210μs	1.2μs	9.05μs	0.21	20.61 KB
#5964	`SendRequest`	net472	0.00161ns	0.000597ns	0.00224ns	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	562μs	2.52μs	9.77μs	0.553	0	0	41.74 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	662μs	1.64μs	6.13μs	0.319	0	0	41.89 KB
master	`WriteAndFlushEnrichedTraces`	net472	879μs	2.86μs	11.1μs	8.62	2.59	0.431	53.27 KB
#5964	`WriteAndFlushEnrichedTraces`	net6.0	547μs	938ns	3.51μs	0.566	0	0	41.6 KB
#5964	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	679μs	1.43μs	5.16μs	0.342	0	0	41.78 KB
#5964	`WriteAndFlushEnrichedTraces`	net472	866μs	3.73μs	14.5μs	8.13	2.57	0.428	53.28 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`ExecuteNonQuery`	net6.0	1.14μs	0.799ns	3.1ns	0.0144	1.02 KB
master	`ExecuteNonQuery`	netcoreapp3.1	1.72μs	1.24ns	4.63ns	0.0137	1.02 KB
master	`ExecuteNonQuery`	net472	2.13μs	2.02ns	7.83ns	0.156	987 B
#5964	`ExecuteNonQuery`	net6.0	1.2μs	0.833ns	3.22ns	0.0144	1.02 KB
#5964	`ExecuteNonQuery`	netcoreapp3.1	1.73μs	1.7ns	6.6ns	0.0137	1.02 KB
#5964	`ExecuteNonQuery`	net472	2.05μs	2.53ns	9.81ns	0.156	987 B

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`CallElasticsearch`	net6.0	1.25μs	0.831ns	3.22ns	0.0138	976 B
master	`CallElasticsearch`	netcoreapp3.1	1.56μs	0.959ns	3.46ns	0.0133	976 B
master	`CallElasticsearch`	net472	2.44μs	1.52ns	5.71ns	0.158	995 B
master	`CallElasticsearchAsync`	net6.0	1.22μs	0.607ns	2.35ns	0.0135	952 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.65μs	0.822ns	3.18ns	0.014	1.02 KB
master	`CallElasticsearchAsync`	net472	2.56μs	1.88ns	7.28ns	0.166	1.05 KB
#5964	`CallElasticsearch`	net6.0	1.32μs	1.17ns	4.52ns	0.0133	976 B
#5964	`CallElasticsearch`	netcoreapp3.1	1.6μs	0.49ns	1.83ns	0.0129	976 B
#5964	`CallElasticsearch`	net472	2.39μs	2.04ns	7.91ns	0.158	995 B
#5964	`CallElasticsearchAsync`	net6.0	1.33μs	0.874ns	3.39ns	0.0133	952 B
#5964	`CallElasticsearchAsync`	netcoreapp3.1	1.6μs	1.35ns	5.22ns	0.0135	1.02 KB
#5964	`CallElasticsearchAsync`	net472	2.46μs	1.63ns	6.32ns	0.167	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.22μs	0.816ns	3.05ns	0.0134	952 B
master	`ExecuteAsync`	netcoreapp3.1	1.61μs	1.07ns	4.01ns	0.0129	952 B
master	`ExecuteAsync`	net472	1.75μs	0.758ns	2.84ns	0.145	915 B
#5964	`ExecuteAsync`	net6.0	1.34μs	1.25ns	4.68ns	0.0133	952 B
#5964	`ExecuteAsync`	netcoreapp3.1	1.7μs	0.855ns	3.2ns	0.0128	952 B
#5964	`ExecuteAsync`	net472	1.8μs	0.499ns	1.93ns	0.145	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.15μs	1.48ns	5.56ns	0.0311	2.22 KB
master	`SendAsync`	netcoreapp3.1	5.19μs	2.47ns	9.56ns	0.0363	2.76 KB
master	`SendAsync`	net472	7.76μs	3.66ns	14.2ns	0.497	3.15 KB
#5964	`SendAsync`	net6.0	4.15μs	2.08ns	7.79ns	0.0311	2.22 KB
#5964	`SendAsync`	netcoreapp3.1	5.1μs	4.22ns	15.8ns	0.0359	2.76 KB
#5964	`SendAsync`	net472	7.84μs	2.03ns	7.87ns	0.496	3.15 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.553ns	2.14ns	0.023	1.64 KB
master	`EnrichedLog`	netcoreapp3.1	2.27μs	4.02ns	15.6ns	0.0226	1.64 KB
master	`EnrichedLog`	net472	2.73μs	2.33ns	9.04ns	0.25	1.57 KB
#5964	`EnrichedLog`	net6.0	1.49μs	0.813ns	3.04ns	0.0231	1.64 KB
#5964	`EnrichedLog`	netcoreapp3.1	2.39μs	1.19ns	4.46ns	0.0212	1.64 KB
#5964	`EnrichedLog`	net472	2.86μs	2.72ns	10.5ns	0.25	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	118μs	118ns	456ns	0.059	0	4.28 KB
master	`EnrichedLog`	netcoreapp3.1	121μs	208ns	777ns	0	0	4.28 KB
master	`EnrichedLog`	net472	148μs	156ns	585ns	0.681	0.227	4.46 KB
#5964	`EnrichedLog`	net6.0	117μs	292ns	1.13μs	0.0574	0	4.28 KB
#5964	`EnrichedLog`	netcoreapp3.1	120μs	170ns	659ns	0	0	4.28 KB
#5964	`EnrichedLog`	net472	149μs	279ns	1.08μs	0.664	0.221	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	2.99μs	1.2ns	4.63ns	0.0315	2.2 KB
master	`EnrichedLog`	netcoreapp3.1	4.02μs	0.983ns	3.54ns	0.0304	2.2 KB
master	`EnrichedLog`	net472	4.89μs	0.994ns	3.58ns	0.319	2.02 KB
#5964	`EnrichedLog`	net6.0	3.19μs	0.831ns	3.11ns	0.0304	2.2 KB
#5964	`EnrichedLog`	netcoreapp3.1	4.09μs	1.25ns	4.85ns	0.0288	2.2 KB
#5964	`EnrichedLog`	net472	4.88μs	0.674ns	2.61ns	0.319	2.02 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`SendReceive`	net6.0	1.31μs	0.45ns	1.68ns	0.0163	0	1.14 KB
master	`SendReceive`	netcoreapp3.1	1.77μs	0.777ns	3.01ns	0.0152	0	1.14 KB
master	`SendReceive`	net472	2.21μs	1.51ns	5.43ns	0.184	0	1.16 KB
#5964	`SendReceive`	net6.0	1.41μs	2.01ns	7.78ns	0.0161	0	1.14 KB
#5964	`SendReceive`	netcoreapp3.1	1.68μs	8.11ns	31.4ns	0.0151	0	1.14 KB
#5964	`SendReceive`	net472	2.12μs	1.14ns	4.43ns	0.183	0.00107	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.62μs	0.771ns	2.99ns	0.0224	1.6 KB
master	`EnrichedLog`	netcoreapp3.1	3.96μs	0.997ns	3.73ns	0.0218	1.65 KB
master	`EnrichedLog`	net472	4.25μs	2.88ns	11.2ns	0.322	2.04 KB
#5964	`EnrichedLog`	net6.0	2.78μs	0.925ns	3.58ns	0.0222	1.6 KB
#5964	`EnrichedLog`	netcoreapp3.1	3.8μs	1.8ns	6.97ns	0.0229	1.65 KB
#5964	`EnrichedLog`	net472	4.42μs	1.28ns	4.61ns	0.323	2.04 KB

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

Slower ⚠️ in #5964

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑netcoreapp3.1	1.138	543.16	618.38
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net472	1.131	580.81	657.05

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net6.0	389ns	0.0744ns	0.288ns	0.00804	576 B
master	`StartFinishSpan`	netcoreapp3.1	543ns	0.154ns	0.557ns	0.00785	576 B
master	`StartFinishSpan`	net472	585ns	1.93ns	7.48ns	0.0917	578 B
master	`StartFinishScope`	net6.0	479ns	0.185ns	0.716ns	0.00981	696 B
master	`StartFinishScope`	netcoreapp3.1	679ns	0.368ns	1.42ns	0.00945	696 B
master	`StartFinishScope`	net472	845ns	1.02ns	3.68ns	0.104	658 B
#5964	`StartFinishSpan`	net6.0	397ns	0.117ns	0.451ns	0.00798	576 B
#5964	`StartFinishSpan`	netcoreapp3.1	618ns	0.536ns	1.86ns	0.00768	576 B
#5964	`StartFinishSpan`	net472	657ns	0.409ns	1.59ns	0.0918	578 B
#5964	`StartFinishScope`	net6.0	483ns	0.178ns	0.667ns	0.00968	696 B
#5964	`StartFinishScope`	netcoreapp3.1	721ns	0.356ns	1.38ns	0.00928	696 B
#5964	`StartFinishScope`	net472	864ns	0.812ns	3.14ns	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	685ns	0.288ns	1.12ns	0.00958	696 B
master	`RunOnMethodBegin`	netcoreapp3.1	858ns	0.308ns	1.11ns	0.00904	696 B
master	`RunOnMethodBegin`	net472	1.07μs	0.772ns	2.99ns	0.104	658 B
#5964	`RunOnMethodBegin`	net6.0	629ns	0.568ns	2.2ns	0.00976	696 B
#5964	`RunOnMethodBegin`	netcoreapp3.1	936ns	0.518ns	2.01ns	0.00938	696 B
#5964	`RunOnMethodBegin`	net472	1.15μs	0.714ns	2.76ns	0.104	658 B

andrewlock · 2024-08-30T10:40:46Z

Throughput/Crank Report ⚡

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 (5964) (11.122M)   : 0, 11122021
    master (11.247M)   : 0, 11246521
    benchmarks/2.9.0 (11.120M)   : 0, 11120231

    section Automatic
    This PR (5964) (7.474M)   : 0, 7474281
    master (7.508M)   : 0, 7508439
    benchmarks/2.9.0 (7.874M)   : 0, 7874046

    section Trace stats
    master (7.707M)   : 0, 7707332

    section Manual
    master (11.233M)   : 0, 11232811

    section Manual + Automatic
    This PR (5964) (6.912M)   : 0, 6911976
    master (6.892M)   : 0, 6891553

    section DD_TRACE_ENABLED=0
    master (10.225M)   : 0, 10225326

gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (5964) (9.742M)   : 0, 9741774
    benchmarks/2.9.0 (9.342M)   : 0, 9341974

    section Automatic
    This PR (5964) (6.756M)   : 0, 6755665

    section Manual + Automatic
    This PR (5964) (6.146M)   : 0, 6146238

gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (5964) (10.083M)   : 0, 10082868
    master (10.060M)   : 0, 10059520
    benchmarks/2.9.0 (10.105M)   : 0, 10105239

    section Automatic
    This PR (5964) (6.599M)   : 0, 6599259
    master (6.690M)   : 0, 6690107
    benchmarks/2.9.0 (7.518M)   : 0, 7517801

    section Trace stats
    master (7.324M)   : 0, 7324117

    section Manual
    master (10.131M)   : 0, 10131126

    section Manual + Automatic
    This PR (5964) (6.008M)   : 0, 6007541
    master (6.279M)   : 0, 6279338

    section DD_TRACE_ENABLED=0
    master (9.441M)   : 0, 9441325

andrewlock

Yup. That's definitely bash.

gleocadie

LGTM

Display the crash tests stdout live

dc21e1c

github-actions bot added the area:builds project files, build scripts, pipelines, versioning, releases, packages label Aug 30, 2024

bash magic

fb0d876

kevingosse marked this pull request as ready for review August 30, 2024 15:01

kevingosse requested a review from a team as a code owner August 30, 2024 15:01

andrewlock approved these changes Sep 2, 2024

View reviewed changes

gleocadie approved these changes Sep 3, 2024

View reviewed changes

kevingosse merged commit d1e7fc3 into master Sep 4, 2024
67 of 70 checks passed

kevingosse deleted the kevin/smoke_test_output branch September 4, 2024 09:54

github-actions bot added this to the vNext-v3 milestone Sep 4, 2024

andrewlock added the area:crashtracking label Oct 23, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Display the crash tests stdout live #5964

Display the crash tests stdout live #5964

kevingosse commented Aug 30, 2024 •

edited

Loading

datadog-ddstaging bot commented Aug 30, 2024 •

edited

Loading

andrewlock commented Aug 30, 2024 •

edited

Loading

andrewlock commented Aug 30, 2024 •

edited

Loading

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #5964

Raw results

Raw results

andrewlock commented Aug 30, 2024

andrewlock left a comment

gleocadie left a comment

Display the crash tests stdout live #5964

Display the crash tests stdout live #5964

Conversation

kevingosse commented Aug 30, 2024 • edited Loading

Summary of changes

Reason for change

Implementation details

datadog-ddstaging bot commented Aug 30, 2024 • edited Loading

Datadog Report

❌ Failed Tests (1)

andrewlock commented Aug 30, 2024 • edited Loading

Execution-Time Benchmarks Report ⏱️

andrewlock commented Aug 30, 2024 • edited Loading

Benchmarks Report for tracer 🐌

Benchmark details

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #5964

Raw results

Raw results

andrewlock commented Aug 30, 2024

Throughput/Crank Report ⚡

andrewlock left a comment

Choose a reason for hiding this comment

gleocadie left a comment

Choose a reason for hiding this comment

kevingosse commented Aug 30, 2024 •

edited

Loading

datadog-ddstaging bot commented Aug 30, 2024 •

edited

Loading

andrewlock commented Aug 30, 2024 •

edited

Loading

andrewlock commented Aug 30, 2024 •

edited

Loading