Skip to content
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

[Profiler] Signal-based profiler/Non-Signal-based: prevent deadlock #5808

Merged

Conversation

gleocadie
Copy link
Collaborator

@gleocadie gleocadie commented Jul 25, 2024

Summary of changes

Prevent deadlock betwen signal-based profilers (walltime/manual cpu profilers) and non-signal based profilers (exception, contention....)

Reason for change

When an exception occurs, the thread can be interrupted by a signal-based profiler (walltime/manual cpu). It can be interrupted while holding the lock used to update the dl-iterate-phdr cache.

Thread 18 (LWP 995):
#0  __syscall_cp_c (nr=202, u=140244538814536, v=128, w=-1, x=0, y=0, z=0) at ./arch/x86_64/syscall_arch.h:61
#1  0x00007f8dba343ccd in __futex4_cp (to=0x0, val=-1, op=128, addr=0x7f8d39eaf048 <LibrariesInfoCache::Get()::Instance>) at src/thread/__timedwait.c:24
#2  __timedwait_cp (addr=addr@entry=0x7f8d39eaf048 <LibrariesInfoCache::Get()::Instance>, val=val@entry=-1, clk=clk@entry=0, at=at@entry=0x0, priv=priv@entry=128) at src/thread/__timedwait.c:52
#3  0x00007f8dba343d74 in __timedwait (addr=addr@entry=0x7f8d39eaf048 <LibrariesInfoCache::Get()::Instance>, val=-1, clk=clk@entry=0, at=at@entry=0x0, priv=128) at src/thread/__timedwait.c:68
#4  0x00007f8dba3463e6 in __pthread_rwlock_timedrdlock (at=<optimized out>, rw=<optimized out>) at src/thread/pthread_rwlock_timedrdlock.c:18
#5  __pthread_rwlock_timedrdlock (rw=0x7f8d39eaf048 <LibrariesInfoCache::Get()::Instance>, at=0x0) at src/thread/pthread_rwlock_timedrdlock.c:3
#6  0x00007f8d398f3ca8 in std::__glibcxx_rwlock_rdlock (__rwlock=0x7f8d39eaf048 <LibrariesInfoCache::Get()::Instance>) at /usr/lib/gcc/x86_64-alpine-linux-musl/10.3.1/../../../../include/c++/10.3.1/shared_mutex:73
#7  std::__shared_mutex_pthread::lock_shared (this=0x7f8d39eaf048 <LibrariesInfoCache::Get()::Instance>) at /usr/lib/gcc/x86_64-alpine-linux-musl/10.3.1/../../../../include/c++/10.3.1/shared_mutex:224
#8  std::shared_mutex::lock_shared (this=0x7f8d39eaf048 <LibrariesInfoCache::Get()::Instance>) at /usr/lib/gcc/x86_64-alpine-linux-musl/10.3.1/../../../../include/c++/10.3.1/shared_mutex:421
#9  std::shared_lock<std::shared_mutex>::shared_lock (this=0x7f4ca05a2ac0, __m=...) at /usr/lib/gcc/x86_64-alpine-linux-musl/10.3.1/../../../../include/c++/10.3.1/shared_mutex:722
#10 LibrariesInfoCache::DlIteratePhdrImpl (this=0x7f8d39eaf048 <LibrariesInfoCache::Get()::Instance>, callback=0x7f8d3997d900 <_Ux86_64_dwarf_callback>, data=0x7f4ca05a2b20) at /project/profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/LibrariesInfoCache.cpp:104
#11 0x00007f8d3997e4ee in _Ux86_64_dwarf_find_proc_info (as=0x7f8d39eb2a00 <local_addr_space>, ip=140246691112115, pi=0x7f4ca05a3170, need_unwind_info=1, arg=0x7f4ca05a3411) at /project/obj/libunwind-prefix/src/libunwind/src/dwarf/Gfind_proc_info-lsb.c:807
#12 0x00007f8d3997e690 in fetch_proc_info (c=0x7f4ca05a3018, ip=140246691112115) at /project/obj/libunwind-prefix/src/libunwind/src/dwarf/Gparser.c:473
#13 0x00007f8d3998113d in find_reg_state (sr=0x7f4ca05a2dc0, c=0x7f4ca05a3018) at /project/obj/libunwind-prefix/src/libunwind/src/dwarf/Gparser.c:1024
#14 _Ux86_64_dwarf_step (c=c@entry=0x7f4ca05a3018) at /project/obj/libunwind-prefix/src/libunwind/src/dwarf/Gparser.c:1069
#15 0x00007f8d3997d13a in _Ux86_64_step (cursor=0x7f4ca05a3018) at /project/obj/libunwind-prefix/src/libunwind/src/x86_64/Gstep.c:75
#16 0x00007f8d398f55c8 in LinuxStackFramesCollector::CollectStackManually (this=this@entry=0x7f8d392dc6d0, ctx=ctx@entry=0x7f4ca05a3880) at /project/profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/LinuxStackFramesCollector.cpp:288
#17 0x00007f8d398f53dc in LinuxStackFramesCollector::CollectCallStackCurrentThread (this=this@entry=0x7f8d392dc6d0, ctx=ctx@entry=0x7f4ca05a3880) at /project/profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/LinuxStackFramesCollector.cpp:227
#18 0x00007f8d398f4672 in LinuxStackFramesCollector::CollectStackSampleSignalHandler (signal=<optimized out>, info=<optimized out>, context=0x7f4ca05a3880) at /project/profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/LinuxStackFramesCollector.cpp:373
#19 0x00007f8d398fb871 in ProfilerSignalManager::CallCustomHandler (this=0x7f8d39eaf928 <ProfilerSignalManager::Get(int)::signalManagers+1944>, signal=10, info=0x7f4ca05a39b0, context=0x7f4ca05a3880) at /project/profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/ProfilerSignalManager.cpp:197
#20 ProfilerSignalManager::SignalHandler (signal=10, info=0x7f4ca05a39b0, context=0x7f4ca05a3880) at /project/profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/ProfilerSignalManager.cpp:188
#21 <signal handler called>
#22 __pthread_rwlock_unlock (rw=0x7f8d39eaf048 <LibrariesInfoCache::Get()::Instance>) at src/thread/pthread_rwlock_unlock.c:5
#23 0x00007f8d398f3bf9 in std::__glibcxx_rwlock_unlock (__rwlock=0x7f8d39eaf048 <LibrariesInfoCache::Get()::Instance>) at /usr/lib/gcc/x86_64-alpine-linux-musl/10.3.1/../../../../include/c++/10.3.1/shared_mutex:77
#24 std::__shared_mutex_pthread::unlock (this=0x7f8d39eaf048 <LibrariesInfoCache::Get()::Instance>) at /usr/lib/gcc/x86_64-alpine-linux-musl/10.3.1/../../../../include/c++/10.3.1/shared_mutex:208
#25 std::shared_mutex::unlock (this=0x7f8d39eaf048 <LibrariesInfoCache::Get()::Instance>) at /usr/lib/gcc/x86_64-alpine-linux-musl/10.3.1/../../../../include/c++/10.3.1/shared_mutex:417
#26 std::unique_lock<std::shared_mutex>::unlock (this=0x7f4ca05a3e20) at /usr/lib/gcc/x86_64-alpine-linux-musl/10.3.1/../../../../include/c++/10.3.1/bits/unique_lock.h:194
#27 std::unique_lock<std::shared_mutex>::~unique_lock (this=0x7f4ca05a3e20) at /usr/lib/gcc/x86_64-alpine-linux-musl/10.3.1/../../../../include/c++/10.3.1/bits/unique_lock.h:103
#28 LibrariesInfoCache::UpdateCache (this=0x7f8d39eaf048 <LibrariesInfoCache::Get()::Instance>) at /project/profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/LibrariesInfoCache.cpp:88
#29 0x00007f8d398f4e59 in LinuxStackFramesCollector::CollectStackSampleImplementation (this=0x7f8d3b91bc90, pThreadInfo=0x7f4ca06b9900, pHR=0x7f8d3a63c510, selfCollect=true) at /p--Type <RET> for more, q to quit, c to continue without paging--
roject/profiler/src/ProfilerEngine/Datadog.Profiler.Native.Linux/LinuxStackFramesCollector.cpp:100
#30 0x00007f8d399637ba in StackFramesCollectorBase::CollectStackSample (this=0x7f8d3b91bc90, pThreadInfo=0x7f4ca06b9900, pHR=0x7f4ca05a3fdc) at /project/profiler/src/ProfilerEngine/Datadog.Profiler.Native/StackFramesCollectorBase.cpp:185
#31 0x00007f8d3992acb9 in ExceptionsProvider::OnExceptionThrown (this=0x7f8d392a7160, thrownObjectId=139969739182080) at /project/profiler/src/ProfilerEngine/Datadog.Profiler.Native/ExceptionsProvider.cpp:149
#32 0x00007f8d39917045 in CorProfilerCallback::ExceptionThrown (this=0x7f8d392c0d20, thrownObjectId=139969739182080) at /project/profiler/src/ProfilerEngine/Datadog.Profiler.Native/CorProfilerCallback.cpp:1734

Implementation details

  • move the call which updates the cache after acquiring the thread lock
  • call Update before sending signal

Test coverage

Other details

@github-actions github-actions bot added the area:profiler Issues related to the continous-profiler label Jul 25, 2024
@andrewlock
Copy link
Member

andrewlock commented Jul 25, 2024

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 (5808) - mean (75ms)  : 61, 89
     .   : milestone, 75,
    master - mean (72ms)  : 62, 82
     .   : milestone, 72,

    section CallTarget+Inlining+NGEN
    This PR (5808) - mean (1,054ms)  : 1034, 1074
     .   : milestone, 1054,
    master - mean (1,057ms)  : 1037, 1078
     .   : milestone, 1057,

Loading
gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5808) - mean (109ms)  : 105, 113
     .   : milestone, 109,
    master - mean (109ms)  : 106, 112
     .   : milestone, 109,

    section CallTarget+Inlining+NGEN
    This PR (5808) - mean (754ms)  : 729, 778
     .   : milestone, 754,
    master - mean (758ms)  : 735, 781
     .   : milestone, 758,

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

    section CallTarget+Inlining+NGEN
    This PR (5808) - mean (699ms)  : 677, 721
     .   : milestone, 699,
    master - mean (702ms)  : 680, 724
     .   : milestone, 702,

Loading
gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5808) - mean (193ms)  : 189, 196
     .   : milestone, 193,
    master - mean (192ms)  : 189, 196
     .   : milestone, 192,

    section CallTarget+Inlining+NGEN
    This PR (5808) - mean (1,168ms)  : 1098, 1238
     .   : milestone, 1168,
    master - mean (1,165ms)  : 1122, 1207
     .   : milestone, 1165,

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

    section CallTarget+Inlining+NGEN
    This PR (5808) - mean (960ms)  : 804, 1117
     .   : milestone, 960,
    master - mean (915ms)  : 881, 949
     .   : milestone, 915,

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

    section CallTarget+Inlining+NGEN
    This PR (5808) - mean (1,094ms)  : crit, 685, 1502
     .   : crit, milestone, 1094,
    master - mean (901ms)  : 880, 922
     .   : milestone, 901,

Loading

@datadog-ddstaging
Copy link

datadog-ddstaging bot commented Jul 25, 2024

Datadog Report

Branch report: gleocadie/fix-deadlock-while-updating-dl_iterate_phdr-cache
Commit report: 98084c1
Test service: dd-trace-dotnet

✅ 0 Failed, 342193 Passed, 2020 Skipped, 16h 14m 18.22s Total Time
⌛ 2 Performance Regressions

⌛ Performance Regressions vs Default Branch (2)

  • CallTarget+Inlining+NGEN - Samples.HttpMessageHandler.windows.net60.json.scenarios 1.09s (+203.22ms, +23%) - Details
  • CallTarget+Inlining+NGEN - Samples.HttpMessageHandler.windows.netcoreapp31.json.scenarios 960.49ms (+55.77ms, +6%) - Details

@gleocadie gleocadie marked this pull request as ready for review July 25, 2024 16:16
@gleocadie gleocadie requested a review from a team as a code owner July 25, 2024 16:16
@gleocadie gleocadie force-pushed the gleocadie/fix-deadlock-while-updating-dl_iterate_phdr-cache branch from 8908b83 to e9c80b0 Compare July 25, 2024 16:17
@andrewlock
Copy link
Member

andrewlock commented Jul 25, 2024

Benchmarks Report for tracer 🐌

Benchmarks for #5808 compared to master:

  • 2 benchmarks are faster, with geometric mean 1.155
  • 1 benchmarks are slower, with geometric mean 1.128
  • 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.47μs 41.2ns 260ns 0.0147 0.00736 0 5.42 KB
master StartStopWithChild netcoreapp3.1 10.2μs 55.1ns 326ns 0.0195 0.00976 0 5.62 KB
master StartStopWithChild net472 16μs 65.3ns 253ns 1.01 0.289 0.0962 6.05 KB
#5808 StartStopWithChild net6.0 7.57μs 42.5ns 272ns 0.0151 0.00755 0 5.42 KB
#5808 StartStopWithChild netcoreapp3.1 9.94μs 52.7ns 274ns 0.0198 0.00992 0 5.62 KB
#5808 StartStopWithChild net472 16.3μs 81.8ns 366ns 1.02 0.303 0.0876 6.07 KB
Benchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net6.0 460μs 321ns 1.24μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 632μs 441ns 1.65μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 851μs 606ns 2.27μs 0.422 0 0 3.3 KB
#5808 WriteAndFlushEnrichedTraces net6.0 477μs 277ns 1.04μs 0 0 0 2.7 KB
#5808 WriteAndFlushEnrichedTraces netcoreapp3.1 629μs 363ns 1.41μs 0 0 0 2.7 KB
#5808 WriteAndFlushEnrichedTraces net472 847μs 768ns 2.97μs 0.422 0 0 3.3 KB
Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendRequest net6.0 195μs 1.12μs 8.23μs 0.192 0 0 18.45 KB
master SendRequest netcoreapp3.1 225μs 1.31μs 11.4μs 0.21 0 0 20.61 KB
master SendRequest net472 0.00247ns 0.00112ns 0.00434ns 0 0 0 0 b
#5808 SendRequest net6.0 198μs 1.15μs 10.1μs 0.202 0 0 18.45 KB
#5808 SendRequest netcoreapp3.1 219μs 1.28μs 11.9μs 0.208 0 0 20.61 KB
#5808 SendRequest net472 0.00364ns 0.00108ns 0.0042ns 0 0 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 580μs 1.37μs 5.29μs 0.587 0 0 41.51 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 674μs 3.28μs 13.5μs 0.379 0 0 41.57 KB
master WriteAndFlushEnrichedTraces net472 858μs 3.96μs 15.3μs 8.25 2.6 0.434 53.3 KB
#5808 WriteAndFlushEnrichedTraces net6.0 560μs 1.83μs 6.61μs 0.543 0 0 41.72 KB
#5808 WriteAndFlushEnrichedTraces netcoreapp3.1 692μs 3.67μs 18μs 0.347 0 0 41.67 KB
#5808 WriteAndFlushEnrichedTraces net472 864μs 2.31μs 8.94μs 8.39 2.52 0.419 53.31 KB
Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteNonQuery net6.0 1.29μs 1.15ns 4.44ns 0.0143 0 0 1.02 KB
master ExecuteNonQuery netcoreapp3.1 1.68μs 1.34ns 5.18ns 0.0136 0 0 1.02 KB
master ExecuteNonQuery net472 2.04μs 2.9ns 11.2ns 0.156 0 0 987 B
#5808 ExecuteNonQuery net6.0 1.32μs 2.32ns 8.36ns 0.0138 0 0 1.02 KB
#5808 ExecuteNonQuery netcoreapp3.1 1.68μs 0.873ns 3.27ns 0.0135 0 0 1.02 KB
#5808 ExecuteNonQuery net472 1.99μs 1.98ns 7.68ns 0.157 0 0 987 B
Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master CallElasticsearch net6.0 1.17μs 0.643ns 2.49ns 0.0135 0 0 976 B
master CallElasticsearch netcoreapp3.1 1.55μs 0.889ns 3.44ns 0.0126 0 0 976 B
master CallElasticsearch net472 2.49μs 1.12ns 4.34ns 0.157 0.00125 0 995 B
master CallElasticsearchAsync net6.0 1.33μs 0.539ns 2.09ns 0.0133 0 0 952 B
master CallElasticsearchAsync netcoreapp3.1 1.67μs 0.47ns 1.69ns 0.0142 0 0 1.02 KB
master CallElasticsearchAsync net472 2.59μs 2.45ns 9.5ns 0.166 0 0 1.05 KB
#5808 CallElasticsearch net6.0 1.25μs 0.756ns 2.83ns 0.0139 0 0 976 B
#5808 CallElasticsearch netcoreapp3.1 1.57μs 1.19ns 4.6ns 0.0128 0 0 976 B
#5808 CallElasticsearch net472 2.46μs 1.97ns 7.63ns 0.158 0 0 995 B
#5808 CallElasticsearchAsync net6.0 1.35μs 2.01ns 7.78ns 0.013 0 0 952 B
#5808 CallElasticsearchAsync netcoreapp3.1 1.62μs 1.07ns 3.84ns 0.0139 0 0 1.02 KB
#5808 CallElasticsearchAsync net472 2.7μs 1.42ns 5.12ns 0.166 0 0 1.05 KB
Benchmarks.Trace.GraphQLBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteAsync net6.0 1.22μs 0.348ns 1.25ns 0.0134 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.65μs 1.07ns 4.01ns 0.0132 0 0 952 B
master ExecuteAsync net472 1.66μs 0.893ns 3.46ns 0.145 0 0 915 B
#5808 ExecuteAsync net6.0 1.27μs 1.42ns 5.5ns 0.0133 0 0 952 B
#5808 ExecuteAsync netcoreapp3.1 1.56μs 1.56ns 5.83ns 0.0131 0 0 952 B
#5808 ExecuteAsync net472 1.7μs 0.826ns 3.09ns 0.145 0.000848 0 915 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.15μs 12.3ns 47.7ns 0.0309 0 0 2.22 KB
master SendAsync netcoreapp3.1 5.1μs 2.52ns 9.77ns 0.0356 0 0 2.76 KB
master SendAsync net472 7.69μs 2.68ns 10ns 0.499 0 0 3.15 KB
#5808 SendAsync net6.0 4.09μs 2.18ns 8.17ns 0.0309 0 0 2.22 KB
#5808 SendAsync netcoreapp3.1 5.15μs 1.26ns 4.73ns 0.0361 0 0 2.76 KB
#5808 SendAsync net472 7.65μs 2.3ns 8.93ns 0.497 0 0 3.15 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.57μs 2.83ns 10.6ns 0.0227 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 2.27μs 0.936ns 3.63ns 0.0227 0 0 1.64 KB
master EnrichedLog net472 2.71μs 0.866ns 3.36ns 0.248 0 0 1.57 KB
#5808 EnrichedLog net6.0 1.46μs 1.06ns 4.1ns 0.0233 0 0 1.64 KB
#5808 EnrichedLog netcoreapp3.1 2.22μs 3.01ns 10.8ns 0.0223 0 0 1.64 KB
#5808 EnrichedLog net472 2.83μs 9.8ns 38ns 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 115μs 271ns 1.05μs 0.0571 0 0 4.28 KB
master EnrichedLog netcoreapp3.1 120μs 547ns 2.12μs 0.06 0 0 4.28 KB
master EnrichedLog net472 146μs 156ns 602ns 0.655 0.218 0 4.46 KB
#5808 EnrichedLog net6.0 114μs 106ns 395ns 0.057 0 0 4.28 KB
#5808 EnrichedLog netcoreapp3.1 120μs 211ns 788ns 0.0595 0 0 4.28 KB
#5808 EnrichedLog net472 150μs 204ns 792ns 0.674 0.225 0 4.46 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.01μs 1.47ns 5.69ns 0.0315 0 0 2.2 KB
master EnrichedLog netcoreapp3.1 4.2μs 1.48ns 5.74ns 0.0292 0 0 2.2 KB
master EnrichedLog net472 4.87μs 1.29ns 4.98ns 0.319 0 0 2.02 KB
#5808 EnrichedLog net6.0 3.21μs 0.798ns 2.98ns 0.0305 0 0 2.2 KB
#5808 EnrichedLog netcoreapp3.1 4.15μs 1.01ns 3.79ns 0.029 0 0 2.2 KB
#5808 EnrichedLog net472 4.73μs 1.65ns 6.41ns 0.319 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.34μs 0.842ns 3.26ns 0.0161 0 0 1.14 KB
master SendReceive netcoreapp3.1 1.78μs 0.72ns 2.6ns 0.0152 0 0 1.14 KB
master SendReceive net472 2.1μs 1.26ns 4.9ns 0.183 0.00104 0 1.16 KB
#5808 SendReceive net6.0 1.31μs 0.613ns 2.29ns 0.0163 0 0 1.14 KB
#5808 SendReceive netcoreapp3.1 1.83μs 0.782ns 3.03ns 0.0147 0 0 1.14 KB
#5808 SendReceive net472 2.05μs 1.77ns 6.86ns 0.183 0 0 1.16 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.77μs 1.06ns 4.12ns 0.0222 0 0 1.6 KB
master EnrichedLog netcoreapp3.1 3.84μs 1.49ns 5.76ns 0.0212 0 0 1.65 KB
master EnrichedLog net472 4.48μs 2.87ns 11.1ns 0.323 0 0 2.04 KB
#5808 EnrichedLog net6.0 2.74μs 1.03ns 3.98ns 0.022 0 0 1.6 KB
#5808 EnrichedLog netcoreapp3.1 3.86μs 2.03ns 7.85ns 0.0212 0 0 1.65 KB
#5808 EnrichedLog net472 4.29μs 0.975ns 3.65ns 0.323 0 0 2.04 KB
Benchmarks.Trace.SpanBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #5808

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑netcoreapp3.1 1.128 577.11 650.70

Faster 🎉 in #5808

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0 1.197 582.70 486.82

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 424ns 0.1ns 0.387ns 0.00805 0 0 576 B
master StartFinishSpan netcoreapp3.1 578ns 0.634ns 2.46ns 0.00775 0 0 576 B
master StartFinishSpan net472 596ns 0.639ns 2.48ns 0.0916 0 0 578 B
master StartFinishScope net6.0 583ns 0.484ns 1.88ns 0.0097 0 0 696 B
master StartFinishScope netcoreapp3.1 664ns 0.246ns 0.951ns 0.00936 0 0 696 B
master StartFinishScope net472 877ns 0.217ns 0.839ns 0.104 0 0 658 B
#5808 StartFinishSpan net6.0 405ns 0.197ns 0.764ns 0.00799 0 0 576 B
#5808 StartFinishSpan netcoreapp3.1 652ns 1.14ns 4.4ns 0.00789 0 0 576 B
#5808 StartFinishSpan net472 600ns 1.19ns 4.63ns 0.0915 0 0 578 B
#5808 StartFinishScope net6.0 487ns 0.318ns 1.23ns 0.00976 0 0 696 B
#5808 StartFinishScope netcoreapp3.1 722ns 0.531ns 2.06ns 0.00942 0 0 696 B
#5808 StartFinishScope net472 844ns 0.346ns 1.29ns 0.104 0 0 658 B
Benchmarks.Trace.TraceAnnotationsBenchmark - Faster 🎉 Same allocations ✔️

Faster 🎉 in #5808

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.TraceAnnotationsBenchmark.RunOnMethodBegin‑netcoreapp3.1 1.114 1,046.54 939.61

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master RunOnMethodBegin net6.0 649ns 0.236ns 0.914ns 0.00981 0 0 696 B
master RunOnMethodBegin netcoreapp3.1 1.05μs 0.53ns 1.98ns 0.00946 0 0 696 B
master RunOnMethodBegin net472 1.12μs 0.497ns 1.92ns 0.104 0 0 658 B
#5808 RunOnMethodBegin net6.0 686ns 0.317ns 1.23ns 0.00964 0 0 696 B
#5808 RunOnMethodBegin netcoreapp3.1 940ns 0.373ns 1.44ns 0.0091 0 0 696 B
#5808 RunOnMethodBegin net472 1.12μs 0.285ns 1.11ns 0.104 0 0 658 B

@gleocadie gleocadie force-pushed the gleocadie/fix-deadlock-while-updating-dl_iterate_phdr-cache branch from f03bc33 to 423cab1 Compare July 26, 2024 08:52
@gleocadie gleocadie force-pushed the gleocadie/fix-deadlock-while-updating-dl_iterate_phdr-cache branch from 423cab1 to 569095a Compare July 26, 2024 09:57
@gleocadie gleocadie requested a review from a team as a code owner July 26, 2024 09:57
@andrewlock
Copy link
Member

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 (5808) (11.668M)   : 0, 11668469
    master (11.465M)   : 0, 11464603
    benchmarks/2.9.0 (11.588M)   : 0, 11588162

    section Automatic
    This PR (5808) (7.745M)   : 0, 7745427
    master (7.734M)   : 0, 7734479
    benchmarks/2.9.0 (8.134M)   : 0, 8134412

    section Trace stats
    master (8.035M)   : 0, 8035402

    section Manual
    master (11.648M)   : 0, 11647573

    section Manual + Automatic
    This PR (5808) (7.202M)   : 0, 7201764
    master (7.259M)   : 0, 7259378

    section DD_TRACE_ENABLED=0
    master (10.837M)   : 0, 10836551

Loading
gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (5808) (9.359M)   : 0, 9358552
    master (9.685M)   : 0, 9684942
    benchmarks/2.9.0 (9.524M)   : 0, 9523985

    section Automatic
    This PR (5808) (6.399M)   : 0, 6398944
    master (6.507M)   : 0, 6507084

    section Trace stats
    master (6.822M)   : 0, 6821902

    section Manual
    master (9.550M)   : 0, 9550109

    section Manual + Automatic
    This PR (5808) (6.197M)   : 0, 6196938
    master (6.049M)   : 0, 6048871

    section DD_TRACE_ENABLED=0
    master (9.024M)   : 0, 9024465

Loading
gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (5808) (10.081M)   : 0, 10080517

    section Automatic
    This PR (5808) (7.179M)   : 0, 7178837

    section Manual + Automatic
    This PR (5808) (6.736M)   : 0, 6736094

Loading

@gleocadie gleocadie force-pushed the gleocadie/fix-deadlock-while-updating-dl_iterate_phdr-cache branch from 569095a to 98084c1 Compare July 26, 2024 11:33
@andrewlock andrewlock merged commit 3f94ea6 into master Jul 26, 2024
72 of 77 checks passed
@andrewlock andrewlock deleted the gleocadie/fix-deadlock-while-updating-dl_iterate_phdr-cache branch July 26, 2024 13:09
@github-actions github-actions bot added this to the vNext-v3 milestone Jul 26, 2024
gleocadie added a commit that referenced this pull request Aug 12, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area:profiler Issues related to the continous-profiler
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants