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] Fix Windows 64 bit stack walking #6583

Merged
merged 1 commit into from
Jan 22, 2025

Conversation

chrisnas
Copy link
Contributor

Summary of changes

Fix Windows 64 bit stack walking code

Reason for change

On Windows, 64 bit stack walking failed (maybe after a Visual Studio update). After investigating, it was due to fact that the execution context was retrieved in a function that was inlined before. Since this context is then used in the same method to iterate on different frames, then the stack should not be updated (i.e. not returning from a function call).
The existing code should have always failed but a previous version of the compiler probably decided to inline it. And this is no more the case for VS 17.12.

Implementation details

Move the context retrieval code in the same function that walk the stack

Test coverage

Already covered in all providers that walk the stack

Other details

@chrisnas chrisnas requested a review from a team as a code owner January 22, 2025 13:14
@github-actions github-actions bot added the area:profiler Issues related to the continous-profiler label Jan 22, 2025
@andrewlock
Copy link
Member

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

    section CallTarget+Inlining+NGEN
    This PR (6583) - mean (982ms)  : 956, 1008
     .   : milestone, 982,
    master - mean (985ms)  : 961, 1010
     .   : milestone, 985,

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

    section CallTarget+Inlining+NGEN
    This PR (6583) - mean (684ms)  : 667, 702
     .   : milestone, 684,
    master - mean (684ms)  : 667, 701
     .   : milestone, 684,

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

    section CallTarget+Inlining+NGEN
    This PR (6583) - mean (638ms)  : 621, 654
     .   : milestone, 638,
    master - mean (635ms)  : 619, 650
     .   : milestone, 635,

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

    section CallTarget+Inlining+NGEN
    This PR (6583) - mean (1,093ms)  : 1059, 1128
     .   : milestone, 1093,
    master - mean (1,087ms)  : 1062, 1113
     .   : milestone, 1087,

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

    section CallTarget+Inlining+NGEN
    This PR (6583) - mean (873ms)  : 844, 901
     .   : milestone, 873,
    master - mean (874ms)  : 845, 903
     .   : milestone, 874,

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

    section CallTarget+Inlining+NGEN
    This PR (6583) - mean (849ms)  : 818, 881
     .   : milestone, 849,
    master - mean (854ms)  : 823, 884
     .   : milestone, 854,

Loading

@datadog-ddstaging
Copy link

datadog-ddstaging bot commented Jan 22, 2025

Datadog Report

Branch report: chrisnas/fix_x64_stackwalk
Commit report: 422a2eb
Test service: dd-trace-dotnet

✅ 0 Failed, 248670 Passed, 2470 Skipped, 20h 52m 23.58s Total Time

@andrewlock
Copy link
Member

Benchmarks Report for tracer 🐌

Benchmarks for #6583 compared to master:

  • 1 benchmarks are faster, with geometric mean 1.147
  • 1 benchmarks are slower, with geometric mean 1.187
  • 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.93μs 34.4ns 150ns 0.0159 0.00396 0 5.61 KB
master StartStopWithChild netcoreapp3.1 10.1μs 46.5ns 180ns 0.0147 0.00491 0 5.81 KB
master StartStopWithChild net472 16.4μs 47.6ns 184ns 1.04 0.296 0.0986 6.21 KB
#6583 StartStopWithChild net6.0 7.89μs 44.5ns 315ns 0.0154 0.00386 0 5.62 KB
#6583 StartStopWithChild netcoreapp3.1 10.2μs 57.1ns 391ns 0.0246 0.00983 0 5.8 KB
#6583 StartStopWithChild net472 16.2μs 38.9ns 151ns 1.04 0.3 0.103 6.21 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 465μs 317ns 1.23μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 670μs 293ns 1.13μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 861μs 342ns 1.28μs 0.428 0 0 3.3 KB
#6583 WriteAndFlushEnrichedTraces net6.0 502μs 254ns 984ns 0 0 0 2.7 KB
#6583 WriteAndFlushEnrichedTraces netcoreapp3.1 644μs 315ns 1.18μs 0 0 0 2.7 KB
#6583 WriteAndFlushEnrichedTraces net472 839μs 337ns 1.26μs 0.419 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 130μs 446ns 1.73μs 0.132 0 0 14.47 KB
master SendRequest netcoreapp3.1 146μs 453ns 1.75μs 0.219 0 0 17.27 KB
master SendRequest net472 0.0127ns 0.00368ns 0.0143ns 0 0 0 0 b
#6583 SendRequest net6.0 131μs 468ns 1.81μs 0.195 0 0 14.47 KB
#6583 SendRequest netcoreapp3.1 140μs 708ns 3.08μs 0.21 0 0 17.27 KB
#6583 SendRequest net472 0.00458ns 0.00224ns 0.00866ns 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 586μs 3.04μs 14.6μs 0.573 0 0 41.69 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 711μs 3.94μs 24μs 0.351 0 0 41.49 KB
master WriteAndFlushEnrichedTraces net472 869μs 4.42μs 19.3μs 8.19 2.59 0.431 53.31 KB
#6583 WriteAndFlushEnrichedTraces net6.0 542μs 2.75μs 12.3μs 0.566 0 0 41.51 KB
#6583 WriteAndFlushEnrichedTraces netcoreapp3.1 707μs 3.63μs 18.5μs 0.361 0 0 41.43 KB
#6583 WriteAndFlushEnrichedTraces net472 819μs 3.63μs 13.6μs 8.45 2.53 0.422 53.36 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.26μs 1.17ns 4.51ns 0.0145 0 0 1.02 KB
master ExecuteNonQuery netcoreapp3.1 1.79μs 2.25ns 8.73ns 0.0134 0 0 1.02 KB
master ExecuteNonQuery net472 1.95μs 2.3ns 8.9ns 0.156 0.000976 0 987 B
#6583 ExecuteNonQuery net6.0 1.33μs 0.935ns 3.5ns 0.014 0 0 1.02 KB
#6583 ExecuteNonQuery netcoreapp3.1 1.72μs 2.61ns 10.1ns 0.0137 0 0 1.02 KB
#6583 ExecuteNonQuery net472 2.15μs 1.93ns 7.48ns 0.157 0.00107 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.3μs 0.645ns 2.41ns 0.0138 0 0 976 B
master CallElasticsearch netcoreapp3.1 1.55μs 1.2ns 4.63ns 0.0132 0 0 976 B
master CallElasticsearch net472 2.53μs 1.93ns 7.46ns 0.158 0 0 995 B
master CallElasticsearchAsync net6.0 1.33μs 0.594ns 2.22ns 0.0134 0 0 952 B
master CallElasticsearchAsync netcoreapp3.1 1.6μs 0.998ns 3.73ns 0.0135 0 0 1.02 KB
master CallElasticsearchAsync net472 2.69μs 1.18ns 4.27ns 0.166 0 0 1.05 KB
#6583 CallElasticsearch net6.0 1.19μs 0.415ns 1.55ns 0.0137 0 0 976 B
#6583 CallElasticsearch netcoreapp3.1 1.59μs 1.84ns 6.9ns 0.0134 0 0 976 B
#6583 CallElasticsearch net472 2.55μs 1.81ns 6.77ns 0.158 0 0 995 B
#6583 CallElasticsearchAsync net6.0 1.42μs 0.734ns 2.65ns 0.013 0 0 952 B
#6583 CallElasticsearchAsync netcoreapp3.1 1.64μs 0.74ns 2.77ns 0.0133 0 0 1.02 KB
#6583 CallElasticsearchAsync net472 2.71μs 1.83ns 7.09ns 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.34μs 0.474ns 1.77ns 0.0135 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.58μs 1.62ns 6.07ns 0.0126 0 0 952 B
master ExecuteAsync net472 1.86μs 0.532ns 2.06ns 0.145 0 0 915 B
#6583 ExecuteAsync net6.0 1.42μs 0.543ns 2.03ns 0.0135 0 0 952 B
#6583 ExecuteAsync netcoreapp3.1 1.64μs 2.45ns 9.51ns 0.013 0 0 952 B
#6583 ExecuteAsync net472 1.81μs 0.447ns 1.67ns 0.145 0 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.35μs 2.24ns 8.39ns 0.0329 0 0 2.31 KB
master SendAsync netcoreapp3.1 5.33μs 2.03ns 7.85ns 0.0373 0 0 2.85 KB
master SendAsync net472 7.34μs 1.84ns 7.11ns 0.495 0 0 3.12 KB
#6583 SendAsync net6.0 4.35μs 1.7ns 6.11ns 0.0326 0 0 2.31 KB
#6583 SendAsync netcoreapp3.1 5.28μs 1.88ns 7.04ns 0.037 0 0 2.85 KB
#6583 SendAsync net472 7.31μs 1.62ns 6.26ns 0.494 0 0 3.12 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.43μs 1.14ns 4.25ns 0.0229 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 2.23μs 0.685ns 2.47ns 0.0222 0 0 1.64 KB
master EnrichedLog net472 2.54μs 1.49ns 5.77ns 0.25 0 0 1.57 KB
#6583 EnrichedLog net6.0 1.5μs 2.46ns 9.21ns 0.0232 0 0 1.64 KB
#6583 EnrichedLog netcoreapp3.1 2.15μs 2.63ns 9.84ns 0.0215 0 0 1.64 KB
#6583 EnrichedLog net472 2.61μs 0.871ns 3.37ns 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 116μs 112ns 433ns 0.0579 0 0 4.28 KB
master EnrichedLog netcoreapp3.1 120μs 254ns 951ns 0 0 0 4.28 KB
master EnrichedLog net472 151μs 142ns 549ns 0.684 0.228 0 4.46 KB
#6583 EnrichedLog net6.0 117μs 131ns 507ns 0.0584 0 0 4.28 KB
#6583 EnrichedLog netcoreapp3.1 120μs 147ns 549ns 0.0603 0 0 4.28 KB
#6583 EnrichedLog net472 151μs 137ns 529ns 0.682 0.227 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 2.98μs 1.02ns 3.94ns 0.0309 0 0 2.2 KB
master EnrichedLog netcoreapp3.1 4.13μs 2.63ns 10.2ns 0.0289 0 0 2.2 KB
master EnrichedLog net472 4.98μs 1.33ns 5.13ns 0.32 0 0 2.02 KB
#6583 EnrichedLog net6.0 3μs 0.879ns 3.41ns 0.0304 0 0 2.2 KB
#6583 EnrichedLog netcoreapp3.1 4.05μs 1.72ns 6.68ns 0.0284 0 0 2.2 KB
#6583 EnrichedLog net472 4.71μs 1.19ns 4.62ns 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.32μs 0.755ns 2.92ns 0.0158 0 0 1.14 KB
master SendReceive netcoreapp3.1 1.81μs 0.395ns 1.42ns 0.0153 0 0 1.14 KB
master SendReceive net472 2.22μs 1.12ns 4.33ns 0.183 0 0 1.16 KB
#6583 SendReceive net6.0 1.39μs 0.414ns 1.55ns 0.0159 0 0 1.14 KB
#6583 SendReceive netcoreapp3.1 1.7μs 1.12ns 4.18ns 0.0153 0 0 1.14 KB
#6583 SendReceive net472 2.13μs 1.21ns 4.67ns 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.82μs 1.18ns 4.57ns 0.0226 0 0 1.6 KB
master EnrichedLog netcoreapp3.1 3.81μs 1.45ns 5.63ns 0.021 0 0 1.65 KB
master EnrichedLog net472 4.31μs 6.23ns 24.1ns 0.322 0 0 2.04 KB
#6583 EnrichedLog net6.0 2.78μs 0.527ns 2.04ns 0.0222 0 0 1.6 KB
#6583 EnrichedLog netcoreapp3.1 3.9μs 1.48ns 5.55ns 0.0215 0 0 1.65 KB
#6583 EnrichedLog net472 4.35μs 2.54ns 9.5ns 0.324 0 0 2.04 KB
Benchmarks.Trace.SpanBenchmark - Faster 🎉 Same allocations ✔️

Faster 🎉 in #6583

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

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 452ns 0.614ns 2.38ns 0.00813 0 0 576 B
master StartFinishSpan netcoreapp3.1 564ns 0.835ns 3.01ns 0.00773 0 0 576 B
master StartFinishSpan net472 600ns 1.25ns 4.84ns 0.0918 0 0 578 B
master StartFinishScope net6.0 536ns 0.73ns 2.83ns 0.00984 0 0 696 B
master StartFinishScope netcoreapp3.1 687ns 1.67ns 6.48ns 0.00963 0 0 696 B
master StartFinishScope net472 868ns 1.77ns 6.84ns 0.104 0 0 658 B
#6583 StartFinishSpan net6.0 396ns 0.754ns 2.92ns 0.00814 0 0 576 B
#6583 StartFinishSpan netcoreapp3.1 590ns 1.1ns 4.26ns 0.0079 0 0 576 B
#6583 StartFinishSpan net472 625ns 0.984ns 3.81ns 0.0916 0 0 578 B
#6583 StartFinishScope net6.0 565ns 0.474ns 1.84ns 0.00988 0 0 696 B
#6583 StartFinishScope netcoreapp3.1 698ns 1.57ns 6.07ns 0.00944 0 0 696 B
#6583 StartFinishScope net472 802ns 1.84ns 7.13ns 0.104 0 0 658 B
Benchmarks.Trace.TraceAnnotationsBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #6583

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.TraceAnnotationsBenchmark.RunOnMethodBegin‑netcoreapp3.1 1.187 851.90 1,010.80

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master RunOnMethodBegin net6.0 626ns 0.918ns 3.56ns 0.00978 0 0 696 B
master RunOnMethodBegin netcoreapp3.1 853ns 1.3ns 5.02ns 0.00942 0 0 696 B
master RunOnMethodBegin net472 1.02μs 2ns 7.73ns 0.104 0 0 658 B
#6583 RunOnMethodBegin net6.0 640ns 1.1ns 4.11ns 0.00993 0 0 696 B
#6583 RunOnMethodBegin netcoreapp3.1 1.01μs 1.62ns 5.61ns 0.00957 0 0 696 B
#6583 RunOnMethodBegin net472 1.04μs 2.41ns 9.33ns 0.104 0 0 658 B

@chrisnas chrisnas merged commit a413296 into master Jan 22, 2025
131 of 135 checks passed
@chrisnas chrisnas deleted the chrisnas/fix_x64_stackwalk branch January 22, 2025 16:16
@github-actions github-actions bot added this to the vNext-v3 milestone Jan 22, 2025
andrewlock pushed a commit that referenced this pull request Jan 28, 2025
## Summary of changes
Fix Windows 64 bit stack walking code

## Reason for change
On Windows, 64 bit stack walking failed (maybe after a Visual Studio
update). After investigating, it was due to fact that the execution
context was retrieved in a function that was inlined before. Since this
context is then used in the same method to iterate on different frames,
then the stack should not be updated (i.e. not returning from a function
call).
The existing code should have always failed but a previous version of
the compiler probably decided to inline it. And this is no more the case
for VS 17.12.

## Implementation details
Move the context retrieval code in the same function that walk the stack

## Test coverage
Already covered in all providers that walk the stack

## Other details
<!-- Fixes #{issue} -->

<!-- ⚠️ Note: where possible, please obtain 2 approvals prior to
merging. Unless CODEOWNERS specifies otherwise, for external teams it is
typically best to have one review from a team member, and one review
from apm-dotnet. Trivial changes do not require 2 reviews. -->
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 type:bug
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants