Skip to content

[Profiler] Fix timer_create bug #6811

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

Merged
merged 2 commits into from
Apr 22, 2025
Merged

Conversation

gleocadie
Copy link
Collaborator

@gleocadie gleocadie commented Apr 2, 2025

Summary of changes

Fix a timestamp bug in timer_create-based CPU profiler.

Reason for change

For each sample, we get the timestamp (since EPOCH). This timestamp is used in the timeline view.
For the timer_create-based CPU profiler, we use clock_gettime with CLOCK_MONOTONIC to retrieve the timestamp (signal-safe).
But this clock is not since EPOCH. Instead, we will use CLOCK_REALTIME.

Implementation details

  • Use CLOCK_REALTIME instead of CLOCK_MONOTONIC

Test coverage

In timer_create-based CPU profiler, add a check for timestamps: check that the timestamp of the sample is part of the current collection or the previous one.

Other details

@github-actions github-actions bot added the area:profiler Issues related to the continous-profiler label Apr 2, 2025
@datadog-datadog-prod-us1
Copy link

datadog-datadog-prod-us1 bot commented Apr 2, 2025

Datadog Report

All test runs 26137db 🔗

2 Total Test Services: 0 Failed, 2 Passed

Test Services
Service Name Failed Known Flaky New Flaky Passed Skipped Total Time Test Service View
dd-trace-dotnet 0 0 0 250720 2985 22h 22m 40.41s Link
exploration_tests 0 0 0 22085 3 2m 9.4s Link

@andrewlock
Copy link
Member

andrewlock commented Apr 2, 2025

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 (6811) - mean (70ms)  : 67, 72
     .   : milestone, 70,
    master - mean (70ms)  : 66, 73
     .   : milestone, 70,

    section CallTarget+Inlining+NGEN
    This PR (6811) - mean (1,010ms)  : 987, 1034
     .   : milestone, 1010,
    master - mean (1,011ms)  : 991, 1031
     .   : milestone, 1011,

Loading
gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6811) - mean (104ms)  : 101, 107
     .   : milestone, 104,
    master - mean (104ms)  : 101, 106
     .   : milestone, 104,

    section CallTarget+Inlining+NGEN
    This PR (6811) - mean (698ms)  : 677, 719
     .   : milestone, 698,
    master - mean (695ms)  : 675, 714
     .   : milestone, 695,

Loading
gantt
    title Execution time (ms) FakeDbCommand (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6811) - mean (90ms)  : 88, 92
     .   : milestone, 90,
    master - mean (90ms)  : 88, 92
     .   : milestone, 90,

    section CallTarget+Inlining+NGEN
    This PR (6811) - mean (659ms)  : 639, 678
     .   : milestone, 659,
    master - mean (660ms)  : 644, 675
     .   : milestone, 660,

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

    section CallTarget+Inlining+NGEN
    This PR (6811) - mean (1,118ms)  : 1093, 1143
     .   : milestone, 1118,
    master - mean (1,111ms)  : 1080, 1141
     .   : milestone, 1111,

Loading
gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6811) - mean (269ms)  : 265, 273
     .   : milestone, 269,
    master - mean (269ms)  : 267, 272
     .   : milestone, 269,

    section CallTarget+Inlining+NGEN
    This PR (6811) - mean (881ms)  : 852, 910
     .   : milestone, 881,
    master - mean (883ms)  : 850, 916
     .   : milestone, 883,

Loading
gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6811) - mean (261ms)  : 258, 264
     .   : milestone, 261,
    master - mean (262ms)  : 258, 265
     .   : milestone, 262,

    section CallTarget+Inlining+NGEN
    This PR (6811) - mean (871ms)  : 840, 903
     .   : milestone, 871,
    master - mean (874ms)  : 841, 906
     .   : milestone, 874,

Loading

@andrewlock
Copy link
Member

andrewlock commented Apr 2, 2025

Benchmarks Report for tracer 🐌

Benchmarks for #6811 compared to master:

  • 2 benchmarks are faster, with geometric mean 1.213
  • 3 benchmarks are slower, with geometric mean 1.127
  • 2 benchmarks have fewer allocations
  • 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 ✔️ More allocations ⚠️

More allocations ⚠️ in #6811

Benchmark Base Allocated Diff Allocated Change Change %
Benchmarks.Trace.ActivityBenchmark.StartStopWithChild‑netcoreapp3.1 5.74 KB 5.79 KB 48 B 0.84%

Fewer allocations 🎉 in #6811

Benchmark Base Allocated Diff Allocated Change Change %
Benchmarks.Trace.ActivityBenchmark.StartStopWithChild‑net472 6.13 KB 6.08 KB -53 B -0.86%

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartStopWithChild net6.0 7.67μs 113ns 1.13μs 0 0 0 5.56 KB
master StartStopWithChild netcoreapp3.1 10.5μs 144ns 1.44μs 0 0 0 5.74 KB
master StartStopWithChild net472 15.3μs 86.6ns 613ns 0.934 0.216 0 6.13 KB
#6811 StartStopWithChild net6.0 7.15μs 35.1ns 153ns 0 0 0 5.55 KB
#6811 StartStopWithChild netcoreapp3.1 10.5μs 130ns 1.3μs 0.05 0 0 5.79 KB
#6811 StartStopWithChild net472 15.4μs 86ns 558ns 1.1 0.411 0.137 6.08 KB
Benchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Fewer allocations 🎉

Fewer allocations 🎉 in #6811

Benchmark Base Allocated Diff Allocated Change Change %
Benchmarks.Trace.AgentWriterBenchmark.WriteAndFlushEnrichedTraces‑net472 3.35 KB 3.31 KB -34 B -1.02%

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net6.0 494μs 469ns 1.62μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 669μs 359ns 1.24μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 851μs 417ns 1.62μs 0 0 0 3.35 KB
#6811 WriteAndFlushEnrichedTraces net6.0 511μs 360ns 1.25μs 0 0 0 2.7 KB
#6811 WriteAndFlushEnrichedTraces netcoreapp3.1 694μs 2.95μs 11μs 0 0 0 2.7 KB
#6811 WriteAndFlushEnrichedTraces net472 858μs 2.46μs 9.21μs 0 0 0 3.31 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 131μs 740ns 5.53μs 0 0 0 14.48 KB
master SendRequest netcoreapp3.1 149μs 448ns 1.74μs 0 0 0 17.28 KB
master SendRequest net472 0.00143ns 0.000585ns 0.00226ns 0 0 0 0 b
#6811 SendRequest net6.0 128μs 728ns 5.35μs 0 0 0 14.48 KB
#6811 SendRequest netcoreapp3.1 148μs 516ns 2.25μs 0 0 0 17.28 KB
#6811 SendRequest net472 0.00241ns 0.000843ns 0.00315ns 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 563μs 3.27μs 27.3μs 0 0 0 41.59 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 738μs 7.81μs 77.3μs 0 0 0 41.59 KB
master WriteAndFlushEnrichedTraces net472 892μs 5.23μs 47.9μs 7.81 3.91 0 53.34 KB
#6811 WriteAndFlushEnrichedTraces net6.0 560μs 3.22μs 27.5μs 0 0 0 41.54 KB
#6811 WriteAndFlushEnrichedTraces netcoreapp3.1 684μs 4.15μs 40.9μs 0 0 0 41.72 KB
#6811 WriteAndFlushEnrichedTraces net472 892μs 5.23μs 49.4μs 7.81 0 0 53.47 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.36μs 3.67ns 13.7ns 0.0137 0 0 1.03 KB
master ExecuteNonQuery netcoreapp3.1 1.84μs 4.52ns 17.5ns 0.00904 0 0 1.02 KB
master ExecuteNonQuery net472 2.1μs 5.79ns 22.4ns 0.155 0.0103 0 995 B
#6811 ExecuteNonQuery net6.0 1.33μs 0.849ns 3.18ns 0.0132 0 0 1.03 KB
#6811 ExecuteNonQuery netcoreapp3.1 1.79μs 6.04ns 22.6ns 0.00884 0 0 1.02 KB
#6811 ExecuteNonQuery net472 2.1μs 3.44ns 13.3ns 0.158 0.0105 0 995 B
Benchmarks.Trace.ElasticsearchBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #6811

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.ElasticsearchBenchmark.CallElasticsearch‑netcoreapp3.1 1.128 1,473.58 1,661.59

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master CallElasticsearch net6.0 1.13μs 0.942ns 3.65ns 0.0112 0 0 984 B
master CallElasticsearch netcoreapp3.1 1.47μs 1.28ns 4.77ns 0.00737 0 0 984 B
master CallElasticsearch net472 2.63μs 3.97ns 14.9ns 0.157 0 0 1 KB
master CallElasticsearchAsync net6.0 1.26μs 0.696ns 2.69ns 0.0126 0 0 960 B
master CallElasticsearchAsync netcoreapp3.1 1.66μs 1.1ns 4.13ns 0.00833 0 0 1.03 KB
master CallElasticsearchAsync net472 2.65μs 1.4ns 5.05ns 0.159 0 0 1.06 KB
#6811 CallElasticsearch net6.0 1.17μs 0.758ns 2.94ns 0.0123 0 0 984 B
#6811 CallElasticsearch netcoreapp3.1 1.66μs 1.44ns 5.57ns 0.00829 0 0 984 B
#6811 CallElasticsearch net472 2.44μs 1.49ns 5.57ns 0.159 0 0 1 KB
#6811 CallElasticsearchAsync net6.0 1.23μs 0.881ns 3.3ns 0.0123 0 0 960 B
#6811 CallElasticsearchAsync netcoreapp3.1 1.75μs 2.85ns 11ns 0.00872 0 0 1.03 KB
#6811 CallElasticsearchAsync net472 2.55μs 1.67ns 6.24ns 0.166 0 0 1.06 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.3μs 0.576ns 2ns 0.0132 0 0 960 B
master ExecuteAsync netcoreapp3.1 1.64μs 1.38ns 5.35ns 0.00815 0 0 960 B
master ExecuteAsync net472 1.83μs 1.15ns 4.44ns 0.147 0 0 923 B
#6811 ExecuteAsync net6.0 1.36μs 1.34ns 5ns 0.0135 0 0 960 B
#6811 ExecuteAsync netcoreapp3.1 1.64μs 1.83ns 6.87ns 0.00828 0 0 960 B
#6811 ExecuteAsync net472 1.75μs 1.13ns 4.37ns 0.141 0 0 923 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.33μs 3.21ns 12.4ns 0.0215 0 0 2.32 KB
master SendAsync netcoreapp3.1 5.39μs 4.24ns 15.9ns 0.0269 0 0 2.86 KB
master SendAsync net472 7.47μs 3.95ns 15.3ns 0.483 0 0 3.13 KB
#6811 SendAsync net6.0 4.39μs 2.86ns 11.1ns 0.022 0 0 2.32 KB
#6811 SendAsync netcoreapp3.1 5.18μs 4.22ns 16.3ns 0.0261 0 0 2.86 KB
#6811 SendAsync net472 7.71μs 3.4ns 13.2ns 0.494 0 0 3.13 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.5μs 0.985ns 3.69ns 0.0226 0 0 1.71 KB
master EnrichedLog netcoreapp3.1 2.26μs 1.9ns 7.13ns 0.0232 0 0 1.71 KB
master EnrichedLog net472 2.6μs 2.61ns 10.1ns 0.26 0 0 1.64 KB
#6811 EnrichedLog net6.0 1.63μs 1.15ns 4.45ns 0.0241 0 0 1.71 KB
#6811 EnrichedLog netcoreapp3.1 2.27μs 2.05ns 7.67ns 0.0114 0 0 1.71 KB
#6811 EnrichedLog net472 2.82μs 2.18ns 8.44ns 0.253 0 0 1.64 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 112μs 159ns 617ns 0 0 0 4.32 KB
master EnrichedLog netcoreapp3.1 116μs 166ns 597ns 0 0 0 4.32 KB
master EnrichedLog net472 151μs 255ns 988ns 0 0 0 4.51 KB
#6811 EnrichedLog net6.0 113μs 148ns 554ns 0 0 0 4.32 KB
#6811 EnrichedLog netcoreapp3.1 117μs 225ns 780ns 0 0 0 4.32 KB
#6811 EnrichedLog net472 152μs 275ns 1.07μs 0 0 0 4.51 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.09μs 1.65ns 6.19ns 0.0309 0 0 2.26 KB
master EnrichedLog netcoreapp3.1 4.15μs 1.69ns 6.33ns 0.0208 0 0 2.26 KB
master EnrichedLog net472 4.92μs 2.43ns 9.42ns 0.319 0 0 2.09 KB
#6811 EnrichedLog net6.0 3.08μs 3.15ns 12.2ns 0.0308 0 0 2.26 KB
#6811 EnrichedLog netcoreapp3.1 4.25μs 3.98ns 15.4ns 0.0212 0 0 2.26 KB
#6811 EnrichedLog net472 5μs 2.85ns 10.3ns 0.324 0 0 2.09 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.47μs 1.07ns 4.01ns 0.0147 0 0 1.15 KB
master SendReceive netcoreapp3.1 1.91μs 2.5ns 9ns 0.00949 0 0 1.15 KB
master SendReceive net472 2.07μs 1.69ns 6.32ns 0.175 0 0 1.16 KB
#6811 SendReceive net6.0 1.41μs 0.912ns 3.53ns 0.0141 0 0 1.15 KB
#6811 SendReceive netcoreapp3.1 1.75μs 1.06ns 3.66ns 0.00868 0 0 1.15 KB
#6811 SendReceive net472 2.11μs 1.38ns 5.15ns 0.18 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.89μs 3.77ns 14.6ns 0.0144 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 4μs 11.9ns 46.3ns 0.0197 0 0 1.69 KB
master EnrichedLog net472 4.49μs 2.16ns 7.78ns 0.315 0 0 2.08 KB
#6811 EnrichedLog net6.0 2.71μs 1.73ns 6.48ns 0.0135 0 0 1.64 KB
#6811 EnrichedLog netcoreapp3.1 4.02μs 2.62ns 9.79ns 0.0202 0 0 1.69 KB
#6811 EnrichedLog net472 4.58μs 10.9ns 37.9ns 0.323 0 0 2.08 KB
Benchmarks.Trace.SpanBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #6811

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑netcoreapp3.1 1.130 697.37 787.91

Faster 🎉 in #6811

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net472 1.213 720.32 593.87
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0 1.213 483.56 398.79

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 483ns 0.658ns 2.46ns 0.00729 0 0 584 B
master StartFinishSpan netcoreapp3.1 564ns 0.649ns 2.51ns 0.00564 0 0 584 B
master StartFinishSpan net472 721ns 0.494ns 1.85ns 0.0907 0 0 586 B
master StartFinishScope net6.0 562ns 0.517ns 2ns 0.00838 0 0 704 B
master StartFinishScope netcoreapp3.1 698ns 0.81ns 3.03ns 0.00673 0 0 704 B
master StartFinishScope net472 864ns 0.369ns 1.43ns 0.104 0 0 666 B
#6811 StartFinishSpan net6.0 399ns 0.32ns 1.24ns 0.00827 0 0 584 B
#6811 StartFinishSpan netcoreapp3.1 559ns 0.617ns 2.39ns 0.00557 0 0 584 B
#6811 StartFinishSpan net472 594ns 0.29ns 1.09ns 0.0926 0 0 586 B
#6811 StartFinishScope net6.0 547ns 0.577ns 2.24ns 0.00822 0 0 704 B
#6811 StartFinishScope netcoreapp3.1 788ns 0.711ns 2.75ns 0.00784 0 0 704 B
#6811 StartFinishScope net472 803ns 0.163ns 0.587ns 0.106 0 0 666 B
Benchmarks.Trace.TraceAnnotationsBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #6811

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.TraceAnnotationsBenchmark.RunOnMethodBegin‑netcoreapp3.1 1.123 941.85 1,057.61

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master RunOnMethodBegin net6.0 656ns 0.39ns 1.46ns 0.00991 0 0 704 B
master RunOnMethodBegin netcoreapp3.1 944ns 1.35ns 5.06ns 0.00918 0 0 704 B
master RunOnMethodBegin net472 1.05μs 0.531ns 1.91ns 0.105 0 0 666 B
#6811 RunOnMethodBegin net6.0 698ns 0.469ns 1.82ns 0.00695 0 0 704 B
#6811 RunOnMethodBegin netcoreapp3.1 1.06μs 0.791ns 2.85ns 0.00533 0 0 704 B
#6811 RunOnMethodBegin net472 1.05μs 0.641ns 2.48ns 0.105 0 0 666 B

@gleocadie gleocadie force-pushed the gleocadie/add-check-on-timestamp branch 2 times, most recently from 26c76b4 to 8562e01 Compare April 10, 2025 08:45
@gleocadie gleocadie marked this pull request as ready for review April 10, 2025 08:52
@gleocadie gleocadie requested a review from a team as a code owner April 10, 2025 08:52
@gleocadie gleocadie force-pushed the gleocadie/add-check-on-timestamp branch from 8562e01 to 957f752 Compare April 11, 2025 08:25
@datadog-ddstaging
Copy link

datadog-ddstaging bot commented Apr 11, 2025

Datadog Report

Branch report: gleocadie/add-check-on-timestamp
Commit report: 957f752
Test service: dd-trace-dotnet

✅ 0 Failed, 6 Passed, 0 Skipped, 0s Total Time

Copy link
Contributor

@chrisnas chrisnas left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@gleocadie gleocadie merged commit e7cdc13 into master Apr 22, 2025
133 of 135 checks passed
@gleocadie gleocadie deleted the gleocadie/add-check-on-timestamp branch April 22, 2025 06:47
@github-actions github-actions bot added this to the vNext-v3 milestone Apr 22, 2025
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