[Profiler] Force waiting for the `LibrariesInfoCache` service to be fully started #6338

gleocadie · 2024-11-22T16:41:25Z

Summary of changes

LibrariesInfoCache service must be fully started before starting other services.

Reason for change

LibrariesInfoCache builds a cache of libraries info and provides a custom implementation of dl_iterate_phdr to libunwind. This prevent the profiler ending in deadlock situation (mainly lock inversion).

If the service is not fully started (callback not set for libunwind, cache not populated...), we can have issue to unwind but also be back in deadlock situation.

So we must make sure this service is fully started before starting the other services.

Implementation details

In StartImpl, pass an AutoResetEvent to the worker thread and wait for 2s for the call to Set
In Work, call once the startEvent once the cache is populated.

Test coverage

Difficult to have one for this one :/

Other details

Example of deadlock we face in CI

Thread 30 (LWP 9751):
#0  __syscall_cp_c (nr=202, u=140659226937600, v=128, w=-1, x=0, y=0, z=0) at ./arch/x86_64/syscall_arch.h:61
#1  0x00007fedc73d3ccd in __futex4_cp (to=0x0, val=-1, op=128, addr=0x7fedc7418900 <lock>) at src/thread/__timedwait.c:24
#2  __timedwait_cp (addr=addr@entry=0x7fedc7418900 <lock>, val=val@entry=-1, clk=clk@entry=0, at=at@entry=0x0, priv=priv@entry=128) at src/thread/__timedwait.c:52
#3  0x00007fedc73d3d74 in __timedwait (addr=addr@entry=0x7fedc7418900 <lock>, val=-1, clk=clk@entry=0, at=at@entry=0x0, priv=128) at src/thread/__timedwait.c:68
#4  0x00007fedc73d63e6 in __pthread_rwlock_timedrdlock (at=<optimized out>, rw=<optimized out>) at src/thread/pthread_rwlock_timedrdlock.c:18
#5  __pthread_rwlock_timedrdlock (rw=rw@entry=0x7fedc7418900 <lock>, at=at@entry=0x0) at src/thread/pthread_rwlock_timedrdlock.c:3
#6  0x00007fedc73d636f in __pthread_rwlock_rdlock (rw=rw@entry=0x7fedc7418900 <lock>) at src/thread/pthread_rwlock_rdlock.c:5
#7  0x00007fedc73de832 in dl_iterate_phdr (callback=0x7fedc5456940 <_ULx86_64_dwarf_callback>, data=0x7fedbe62f540) at ldso/dynlink.c:2360
#8  0x00007fedc737e6d4 in dl_iterate_phdr (callback=0x7fedc5456940 <_ULx86_64_dwarf_callback>, data=0x7fedbe62f540) at /project/profiler/src/ProfilerEngine/Datadog.Linux.ApiWrapper/functions_to_wrap.c:367
#9  0x00007fedc545703e in _ULx86_64_dwarf_find_proc_info (as=0x7fedc5b97680 <local_addr_space>, ip=ip@entry=140659226543154, pi=pi@entry=0x7fedbe6300a8, need_unwind_info=need_unwind_info@entry=1, arg=0x7fedbe62fba1) at /project/obj/libunwind-prefix/src/libunwind/src/dwarf/Gfind_proc_info-lsb.c:807
#10 0x00007fedc5452770 in fetch_proc_info (c=0x7fedbe62ff50, ip=140659226543154) at /project/obj/libunwind-prefix/src/libunwind/src/dwarf/Gparser.c:473
#11 0x00007fedc545443d in find_reg_state (sr=0x7fedbe62f7e0, c=0x7fedbe62ff50) at /project/obj/libunwind-prefix/src/libunwind/src/dwarf/Gparser.c:1024
#12 _ULx86_64_dwarf_step (c=c@entry=0x7fedbe62ff50) at /project/obj/libunwind-prefix/src/libunwind/src/dwarf/Gparser.c:1069
#13 0x00007fedc54513ca in _ULx86_64_step (cursor=cursor@entry=0x7fedbe62ff50) at /project/obj/libunwind-prefix/src/libunwind/src/x86_64/Gstep.c:75
#14 0x00007fedc5452217 in trace_init_addr (rsp=<optimized out>, rbp=<optimized out>, rip=140659226543154, cfa=<optimized out>, cursor=0x7fedbe62ff50, f=<optimized out>) at /project/obj/libunwind-prefix/src/libunwind/src/x86_64/Gtrace.c:249
#15 trace_lookup (rsp=<optimized out>, rbp=<optimized out>, rip=140659226543154, cfa=<optimized out>, cache=0x7fedc4b9cee0, cursor=0x7fedbe62ff50) at /project/obj/libunwind-prefix/src/libunwind/src/x86_64/Gtrace.c:331
#16 _ULx86_64_tdep_trace (cursor=cursor@entry=0x7fedbe62ff50, buffer=buffer@entry=0x7fedc31d8008, size=size@entry=0x7fedbe62fb8c) at /project/obj/libunwind-prefix/src/libunwind/src/x86_64/Gtrace.c:449
#17 0x00007fedc5450712 in unw_backtrace2 (buffer=0x7fedc31d8008, size=1024, uc2=0x7fedbe630840, flag=1) at /project/obj/libunwind-prefix/src/libunwind/src/mi/backtrace.c:111
#18 0x00007fedc53b194c in LinuxStackFramesCollector::CollectStackWithBacktrace2 (this=0x7fedc4d1bea0, ctx=0x7fedbe630840) at /project/profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/LinuxStackFramesCollector.cpp:283
#19 LinuxStackFramesCollector::CollectCallStackCurrentThread (this=this@entry=0x7fedc4d1bea0, ctx=ctx@entry=0x7fedbe630840) at /project/profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/LinuxStackFramesCollector.cpp:210
#20 0x00007fedc53b0cd3 in LinuxStackFramesCollector::CollectStackSampleSignalHandler (signal=<optimized out>, info=0x7fedbe630970, context=0x7fedbe630840) at /project/profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/LinuxStackFramesCollector.cpp:378
#21 0x00007fedc53b88e1 in ProfilerSignalManager::CallCustomHandler (this=0x7fedc5b89b08 <ProfilerSignalManager::Get(int)::signalManagers+1944>, signal=10, info=0x7fedbe630970, context=0x7fedbe630840) at /project/profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/ProfilerSignalManager.cpp:197
#22 ProfilerSignalManager::SignalHandler (signal=10, info=0x7fedbe630970, context=0x7fedbe630840) at /project/profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/ProfilerSignalManager.cpp:188
#23 <signal handler called>

datadog-ddstaging · 2024-11-22T17:03:09Z

Datadog Report

Branch report: gleocadie/fix-deadlock
Commit report: ec52ff4
Test service: dd-trace-dotnet

✅ 0 Failed, 454938 Passed, 3225 Skipped, 21h 2m 27.58s Total Time
❄️ 1 New Flaky

New Flaky Tests (1)

AdditionalArguments - Datadog.Trace.Tools.dd_dotnet.ArtifactTests.RunCommandTests - Last Failure

Expand for error

 
 
 With StandardOutput:
 Waiting - PID: 8124 - Main thread: 9984 - Profiler attached: True Args: traces 5 --dd-env test Sending 5 spans 
 With ErrorOutput:
  Unhandled Exception: System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> System.DllNotFoundException: Unable to load DLL 'datadog_profiling_ffi': The specified module could not be found. (Exception from HRESULT: 0x8007007E)    at Datadog.Trace.LibDatadog.TraceExporter.Native.ddog_trace_exporter_new(IntPtr& outHandle, CharSlice url, CharSlice tracerVersion, CharSlice language, CharSlice languageVersion, CharSlice languageInterpreter, CharSlice hostname, CharSlice env, CharSlice version, CharSlice service, TraceExporterInputFormat inputFormat, TraceExporterOutputFormat outputFormat, Boolean computeStats, AgentResponseCallback agentResponseCallback)    at Datadog.Trace.LibDatadog.TraceExporter..ctor(ImmutableTracerSettings settings)    at Datadog.Trace.TracerManagerFactory.GetApi(ImmutableTracerSettings settings, IDogStatsd statsd, Action\`1 updateSampleRates, IApiRequestFactory apiRequestFactory)    at Datadog.Trace.TracerManagerFactory.GetAgentWriter(ImmutableTracerSettings settings, IDogStatsd statsd, Action\`1 updateSampleRates, IDiscoveryService discoveryService)    at Datadog.Trace.Traampler, IScopeManager scopeManager, IDogStatsd statsd, RuntimeMetricsWriter runtimeMetrics, DirectLogSubmissionManager logSubmissionManager, ITelemetryController telemetry, IDiscoveryService discoveryService, DataStreamsManager dataStreamsManager, IRemoteConfigurationManager remoteConfigurationManager, IDynamicConfigurationManager dynamicConfigurationManager, ITracerFlareManager tracerFlareManager)    at Datadog.Trace.TracerManagerFactory.CreateTracerManager(ImmutableTracerSettings settings, TracerManager previous)    at Datadog.Trace.TracerManager.CreateInitializedTracer(ImmutableTracerSettings settings, TracerManagerFactory factory)    at Datadog.Trace.TracerManager.<>c.<get_Instance>b__9_0()    at System.Threading.LazyInitializer.EnsureInitializedCore[T](T& target, Boolean& initialized, Object& syncLock, Func\`1 valueFactory)    at Datadog.Trace.TracerManager.get_Instance()    at Datadog.Trace.Tracer..ctor(TracerManager tracerManager)    at Datadog.Trace.Tracer.get_Instance()    --- End of inner exception stack trace ---    at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor)    at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments)    at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)    at Samples.SampleHelpers.CreateScope(String operationName)    at Samples.Console_.Program.<AsyncMain>d__2.MoveNext() --- End of stack trace from previous location where exception was thrown ---    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)    at Samples.Console_.Program.Main(String[] args) ".

andrewlock · 2024-11-22T17:13:50Z

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 (6338) - mean (69ms)  : 66, 72
     .   : milestone, 69,
    master - mean (69ms)  : 66, 71
     .   : milestone, 69,

    section CallTarget+Inlining+NGEN
    This PR (6338) - mean (981ms)  : 958, 1004
     .   : milestone, 981,
    master - mean (977ms)  : 957, 998
     .   : milestone, 977,

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

    section CallTarget+Inlining+NGEN
    This PR (6338) - mean (677ms)  : 661, 694
     .   : milestone, 677,
    master - mean (679ms)  : 665, 692
     .   : milestone, 679,

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

    section CallTarget+Inlining+NGEN
    This PR (6338) - mean (634ms)  : 621, 647
     .   : milestone, 634,
    master - mean (633ms)  : 617, 648
     .   : milestone, 633,

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

    section CallTarget+Inlining+NGEN
    This PR (6338) - mean (1,096ms)  : 1067, 1126
     .   : milestone, 1096,
    master - mean (1,092ms)  : 1055, 1128
     .   : milestone, 1092,

gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6338) - mean (278ms)  : 271, 285
     .   : milestone, 278,
    master - mean (277ms)  : 273, 281
     .   : milestone, 277,

    section CallTarget+Inlining+NGEN
    This PR (6338) - mean (873ms)  : 842, 903
     .   : milestone, 873,
    master - mean (869ms)  : 842, 895
     .   : milestone, 869,

gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6338) - mean (266ms)  : 262, 270
     .   : milestone, 266,
    master - mean (265ms)  : 261, 269
     .   : milestone, 265,

    section CallTarget+Inlining+NGEN
    This PR (6338) - mean (856ms)  : 826, 886
     .   : milestone, 856,
    master - mean (852ms)  : 818, 886
     .   : milestone, 852,

andrewlock · 2024-11-23T05:53:30Z

Benchmarks Report for tracer 🐌

Benchmarks for #6338 compared to master:

1 benchmarks are slower, with geometric mean 1.114
1 benchmarks have more 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	8μs	45ns	305ns	0.0204	0.00816	0.00408	5.61 KB
master	`StartStopWithChild`	netcoreapp3.1	9.93μs	54.7ns	314ns	0.0147	0.00491	0	5.81 KB
master	`StartStopWithChild`	net472	16.1μs	60.8ns	235ns	1.05	0.318	0.103	6.2 KB
#6338	`StartStopWithChild`	net6.0	7.96μs	43.1ns	262ns	0.0159	0.00797	0	5.61 KB
#6338	`StartStopWithChild`	netcoreapp3.1	9.77μs	47.1ns	240ns	0.0189	0.00944	0	5.8 KB
#6338	`StartStopWithChild`	net472	16.4μs	33.4ns	120ns	1.05	0.309	0.106	6.21 KB

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

Slower ⚠️ in #6338

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.AgentWriterBenchmark.WriteAndFlushEnrichedTraces‑net6.0	1.114	478,710.46	533,141.87

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	479μs	389ns	1.45μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	652μs	217ns	839ns	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	net472	833μs	502ns	1.94μs	0.419	3.3 KB
#6338	`WriteAndFlushEnrichedTraces`	net6.0	528μs	2.97μs	17.1μs	0	2.7 KB
#6338	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	655μs	232ns	838ns	0	2.7 KB
#6338	`WriteAndFlushEnrichedTraces`	net472	847μs	587ns	2.2μ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	151μs	864ns	6.69μs	0.149	14.47 KB
master	`SendRequest`	netcoreapp3.1	162μs	903ns	8.03μs	0.173	17.27 KB
master	`SendRequest`	net472	0ns	0ns	0ns	0	0 b
#6338	`SendRequest`	net6.0	150μs	847ns	6.39μs	0.147	14.47 KB
#6338	`SendRequest`	netcoreapp3.1	174μs	1.22μs	11.9μs	0.154	17.27 KB
#6338	`SendRequest`	net472	0.003ns	0.00109ns	0.00378ns	0	0 b

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

More allocations ⚠️ in #6338

Benchmark	Base Allocated	Diff Allocated	Change	Change %
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark.WriteAndFlushEnrichedTraces‑net6.0	41.49 KB	41.77 KB	280 B	0.67%

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Gen 2	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	567μs	1.45μs	5.02μs	0.558	0	0	41.49 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	671μs	1.51μs	5.23μs	0.345	0	0	41.68 KB
master	`WriteAndFlushEnrichedTraces`	net472	852μs	4.11μs	16.5μs	8.19	2.59	0.431	53.32 KB
#6338	`WriteAndFlushEnrichedTraces`	net6.0	576μs	2.67μs	10μs	0.584	0	0	41.77 KB
#6338	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	693μs	3.81μs	23.8μs	0.349	0	0	41.82 KB
#6338	`WriteAndFlushEnrichedTraces`	net472	871μs	4.38μs	19.1μs	8.87	2.53	0.422	53.29 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.31μs	0.806ns	3.12ns	0.0145	0	1.02 KB
master	`ExecuteNonQuery`	netcoreapp3.1	1.72μs	3.32ns	12.9ns	0.0137	0	1.02 KB
master	`ExecuteNonQuery`	net472	2.03μs	2.2ns	8.53ns	0.156	0.00101	987 B
#6338	`ExecuteNonQuery`	net6.0	1.23μs	0.814ns	3.15ns	0.0142	0	1.02 KB
#6338	`ExecuteNonQuery`	netcoreapp3.1	1.74μs	1.65ns	6.19ns	0.0131	0	1.02 KB
#6338	`ExecuteNonQuery`	net472	2.1μs	1.8ns	6.72ns	0.157	0.00107	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	1.28ns	4.95ns	0.0137	976 B
master	`CallElasticsearch`	netcoreapp3.1	1.51μs	0.693ns	2.59ns	0.013	976 B
master	`CallElasticsearch`	net472	2.5μs	1.46ns	5.67ns	0.158	995 B
master	`CallElasticsearchAsync`	net6.0	1.32μs	0.677ns	2.62ns	0.0132	952 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.65μs	1.1ns	4.12ns	0.0133	1.02 KB
master	`CallElasticsearchAsync`	net472	2.6μs	2.17ns	8.41ns	0.167	1.05 KB
#6338	`CallElasticsearch`	net6.0	1.21μs	0.516ns	2ns	0.0133	976 B
#6338	`CallElasticsearch`	netcoreapp3.1	1.58μs	0.797ns	2.98ns	0.0127	976 B
#6338	`CallElasticsearch`	net472	2.68μs	2.6ns	10.1ns	0.158	995 B
#6338	`CallElasticsearchAsync`	net6.0	1.25μs	0.537ns	2.01ns	0.0131	952 B
#6338	`CallElasticsearchAsync`	netcoreapp3.1	1.67μs	0.693ns	2.5ns	0.0142	1.02 KB
#6338	`CallElasticsearchAsync`	net472	2.69μs	0.709ns	2.56ns	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.29μs	1.63ns	6.31ns	0.0133	952 B
master	`ExecuteAsync`	netcoreapp3.1	1.75μs	0.6ns	2.32ns	0.0131	952 B
master	`ExecuteAsync`	net472	1.86μs	0.532ns	2.06ns	0.145	915 B
#6338	`ExecuteAsync`	net6.0	1.22μs	0.614ns	2.38ns	0.0134	952 B
#6338	`ExecuteAsync`	netcoreapp3.1	1.62μs	1.88ns	7.27ns	0.0123	952 B
#6338	`ExecuteAsync`	net472	1.81μs	0.453ns	1.76ns	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.36μs	1.56ns	5.82ns	0.0329	2.31 KB
master	`SendAsync`	netcoreapp3.1	5.45μs	2.53ns	9.79ns	0.0381	2.85 KB
master	`SendAsync`	net472	7.36μs	1.88ns	7.28ns	0.495	3.12 KB
#6338	`SendAsync`	net6.0	4.48μs	0.791ns	2.96ns	0.0313	2.31 KB
#6338	`SendAsync`	netcoreapp3.1	5.21μs	1.98ns	7.65ns	0.0393	2.85 KB
#6338	`SendAsync`	net472	7.34μs	1.85ns	7.16ns	0.494	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	1ns	3.76ns	0.0232	1.64 KB
master	`EnrichedLog`	netcoreapp3.1	2.3μs	0.827ns	3.09ns	0.0217	1.64 KB
master	`EnrichedLog`	net472	2.74μs	1.64ns	6.34ns	0.25	1.57 KB
#6338	`EnrichedLog`	net6.0	1.43μs	0.557ns	2.16ns	0.0229	1.64 KB
#6338	`EnrichedLog`	netcoreapp3.1	2.26μs	0.956ns	3.7ns	0.0222	1.64 KB
#6338	`EnrichedLog`	net472	2.7μs	1.71ns	6.38ns	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	118μs	243ns	941ns	0	0	4.28 KB
master	`EnrichedLog`	netcoreapp3.1	124μs	133ns	517ns	0.0623	0	4.28 KB
master	`EnrichedLog`	net472	150μs	127ns	474ns	0.675	0.225	4.46 KB
#6338	`EnrichedLog`	net6.0	119μs	163ns	633ns	0.0592	0	4.28 KB
#6338	`EnrichedLog`	netcoreapp3.1	123μs	157ns	609ns	0	0	4.28 KB
#6338	`EnrichedLog`	net472	150μs	157ns	609ns	0.673	0.224	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.03μs	0.798ns	3.09ns	0.0304	2.2 KB
master	`EnrichedLog`	netcoreapp3.1	4.1μs	1.44ns	5.4ns	0.0287	2.2 KB
master	`EnrichedLog`	net472	4.85μs	1.34ns	5.19ns	0.319	2.02 KB
#6338	`EnrichedLog`	net6.0	2.98μs	0.801ns	3.1ns	0.0313	2.2 KB
#6338	`EnrichedLog`	netcoreapp3.1	4.32μs	0.943ns	3.65ns	0.03	2.2 KB
#6338	`EnrichedLog`	net472	4.77μs	0.994ns	3.58ns	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.43μs	1.34ns	5.21ns	0.0157	1.14 KB
master	`SendReceive`	netcoreapp3.1	1.8μs	4.4ns	17ns	0.0153	1.14 KB
master	`SendReceive`	net472	2.26μs	3.5ns	13.6ns	0.183	1.16 KB
#6338	`SendReceive`	net6.0	1.42μs	0.899ns	3.48ns	0.0156	1.14 KB
#6338	`SendReceive`	netcoreapp3.1	1.76μs	1.14ns	4.42ns	0.015	1.14 KB
#6338	`SendReceive`	net472	2.1μs	0.713ns	2.67ns	0.184	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.75μs	1.22ns	4.73ns	0.0221	1.6 KB
master	`EnrichedLog`	netcoreapp3.1	4.12μs	4.86ns	18.8ns	0.0225	1.65 KB
master	`EnrichedLog`	net472	4.32μs	1.18ns	4.26ns	0.323	2.04 KB
#6338	`EnrichedLog`	net6.0	2.79μs	1.1ns	4.13ns	0.0222	1.6 KB
#6338	`EnrichedLog`	netcoreapp3.1	3.88μs	1.28ns	4.95ns	0.0211	1.65 KB
#6338	`EnrichedLog`	net472	4.33μs	2.57ns	9.94ns	0.323	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	511ns	0.7ns	2.71ns	0.00805	576 B
master	`StartFinishSpan`	netcoreapp3.1	619ns	0.898ns	3.48ns	0.00777	576 B
master	`StartFinishSpan`	net472	676ns	1.7ns	6.57ns	0.0918	578 B
master	`StartFinishScope`	net6.0	492ns	0.499ns	1.93ns	0.00971	696 B
master	`StartFinishScope`	netcoreapp3.1	798ns	0.928ns	3.59ns	0.00954	696 B
master	`StartFinishScope`	net472	881ns	1.12ns	4.34ns	0.104	658 B
#6338	`StartFinishSpan`	net6.0	461ns	0.654ns	2.53ns	0.00822	576 B
#6338	`StartFinishSpan`	netcoreapp3.1	595ns	0.697ns	2.7ns	0.00768	576 B
#6338	`StartFinishSpan`	net472	634ns	1.08ns	4.2ns	0.0916	578 B
#6338	`StartFinishScope`	net6.0	490ns	0.883ns	3.42ns	0.00979	696 B
#6338	`StartFinishScope`	netcoreapp3.1	805ns	1.46ns	5.64ns	0.0093	696 B
#6338	`StartFinishScope`	net472	867ns	1.88ns	7.02ns	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	671ns	1.15ns	4.44ns	0.00967	696 B
master	`RunOnMethodBegin`	netcoreapp3.1	885ns	1.57ns	6.07ns	0.00921	696 B
master	`RunOnMethodBegin`	net472	1.18μs	3.02ns	11.7ns	0.104	658 B
#6338	`RunOnMethodBegin`	net6.0	608ns	1.05ns	4.08ns	0.00977	696 B
#6338	`RunOnMethodBegin`	netcoreapp3.1	899ns	2.16ns	8.38ns	0.00953	696 B
#6338	`RunOnMethodBegin`	net472	1.11μs	2.43ns	9.43ns	0.105	658 B

chrisnas

LGTM

andrewlock · 2024-11-26T13:44: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 (6338) (11.328M)   : 0, 11328039
    master (11.163M)   : 0, 11163279
    benchmarks/2.9.0 (11.033M)   : 0, 11032866

    section Automatic
    This PR (6338) (7.341M)   : 0, 7341299
    master (7.379M)   : 0, 7378518
    benchmarks/2.9.0 (7.786M)   : 0, 7785853

    section Trace stats
    master (7.698M)   : 0, 7697685

    section Manual
    master (11.208M)   : 0, 11207970

    section Manual + Automatic
    This PR (6338) (6.732M)   : 0, 6732156
    master (6.848M)   : 0, 6847878

    section DD_TRACE_ENABLED=0
    master (10.300M)   : 0, 10300258

gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6338) (9.531M)   : 0, 9530816
    master (9.614M)   : 0, 9613662
    benchmarks/2.9.0 (9.495M)   : 0, 9494821

    section Automatic
    This PR (6338) (6.431M)   : 0, 6430961
    master (6.420M)   : 0, 6420484

    section Trace stats
    master (6.620M)   : 0, 6620303

    section Manual
    master (9.598M)   : 0, 9598372

    section Manual + Automatic
    This PR (6338) (6.072M)   : 0, 6072031
    master (5.968M)   : 0, 5968390

    section DD_TRACE_ENABLED=0
    master (8.911M)   : 0, 8911128

gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6338) (10.132M)   : 0, 10132311
    master (9.949M)   : 0, 9949075
    benchmarks/2.9.0 (10.020M)   : 0, 10019592

    section Automatic
    This PR (6338) (6.562M)   : 0, 6561671
    master (6.538M)   : 0, 6537814
    benchmarks/2.9.0 (7.255M)   : 0, 7255257

    section Trace stats
    master (7.075M)   : 0, 7075474

    section Manual
    master (9.758M)   : 0, 9757921

    section Manual + Automatic
    This PR (6338) (5.867M)   : 0, 5866936
    master (6.151M)   : 0, 6151047

    section DD_TRACE_ENABLED=0
    master (9.404M)   : 0, 9403695

…ully started (#6338)

github-actions bot added the area:profiler Issues related to the continous-profiler label Nov 22, 2024

gleocadie force-pushed the gleocadie/fix-deadlock branch from 5e4cd40 to 947f563 Compare November 22, 2024 17:35

chrisnas approved these changes Nov 25, 2024

View reviewed changes

gleocadie marked this pull request as ready for review November 26, 2024 11:31

gleocadie requested a review from a team as a code owner November 26, 2024 11:31

gleocadie force-pushed the gleocadie/fix-deadlock branch from 947f563 to 2ff9105 Compare November 26, 2024 11:31

gleocadie force-pushed the gleocadie/fix-deadlock branch from 2ff9105 to 26305c4 Compare November 28, 2024 12:01

gleocadie added 2 commits December 4, 2024 16:02

Force waiting for the LibrariesInfoCache to be fully started

07592a5

Adjust the code

ec52ff4

gleocadie force-pushed the gleocadie/fix-deadlock branch from 26305c4 to ec52ff4 Compare December 4, 2024 15:02

gleocadie merged commit 9216eee into master Dec 5, 2024
112 of 114 checks passed

gleocadie deleted the gleocadie/fix-deadlock branch December 5, 2024 10:10

github-actions bot added this to the vNext-v3 milestone Dec 5, 2024

veerbia pushed a commit that referenced this pull request Dec 16, 2024

[Profiler] Force waiting for the LibrariesInfoCache service to be f…

71bddc6

…ully started (#6338)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Profiler] Force waiting for the `LibrariesInfoCache` service to be fully started #6338

[Profiler] Force waiting for the `LibrariesInfoCache` service to be fully started #6338

gleocadie commented Nov 22, 2024 •

edited

Loading

datadog-ddstaging bot commented Nov 22, 2024 •

edited

Loading

andrewlock commented Nov 22, 2024 •

edited

Loading

andrewlock commented Nov 23, 2024 •

edited

Loading

Raw results

Slower ⚠️ in #6338

Raw results

Raw results

More allocations ⚠️ in #6338

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

chrisnas left a comment

andrewlock commented Nov 26, 2024 •

edited

Loading

[Profiler] Force waiting for the LibrariesInfoCache service to be fully started #6338

[Profiler] Force waiting for the LibrariesInfoCache service to be fully started #6338

Conversation

gleocadie commented Nov 22, 2024 • edited Loading

Summary of changes

Reason for change

Implementation details

Test coverage

Other details

datadog-ddstaging bot commented Nov 22, 2024 • edited Loading

Datadog Report

New Flaky Tests (1)

andrewlock commented Nov 22, 2024 • edited Loading

Execution-Time Benchmarks Report ⏱️

andrewlock commented Nov 23, 2024 • edited Loading

Benchmarks Report for tracer 🐌

Benchmark details

Raw results

Slower ⚠️ in #6338

Raw results

Raw results

More allocations ⚠️ in #6338

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

chrisnas left a comment

Choose a reason for hiding this comment

andrewlock commented Nov 26, 2024 • edited Loading

Throughput/Crank Report ⚡

[Profiler] Force waiting for the `LibrariesInfoCache` service to be fully started #6338

[Profiler] Force waiting for the `LibrariesInfoCache` service to be fully started #6338

gleocadie commented Nov 22, 2024 •

edited

Loading

datadog-ddstaging bot commented Nov 22, 2024 •

edited

Loading

andrewlock commented Nov 22, 2024 •

edited

Loading

andrewlock commented Nov 23, 2024 •

edited

Loading

andrewlock commented Nov 26, 2024 •

edited

Loading