8000 Optimise StackTraceSnippet.Get by benbryant0 · Pull Request #605 · MiniProfiler/dotnet · GitHub
[go: up one dir, main page]
More Web Proxy on the site http://driver.im/
Skip to content

Optimise StackTraceSnippet.Get #605

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.

Sign up for GitHub

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

Jump to bottom
Merged
merged 5 commits into from
May 28, 2022
Merged

Optimise StackTraceSnippet.Get #605

merged 5 commits into from
May 28, 2022

Conversation

benbryant0
Copy link
Contributor
@benbryant0 benbryant0 commented May 6, 2022 •
edited
Loading

TL;DR: Cache the names of System.Reflection.Assembly and System.Reflection.Module instances in a static dictionary as they are non-trivially recomputed on every read of the property. This reduces allocations by ~70% and doubles speed when instantiating CustomTiming with stack traces (the default behaviour).

Instantiating CustomTiming with 'normal' parameters allocated a surprisingly large amount in the benchmarks. A chunk of it is from calling new StackTrace().GetFrames(); which I don't think we can do anything about in a reasonable way.. but most was from reflection, which is almost completely mitigated by these changes.

The problem is that Assembly.GetName().Name and Module.Name don't persist the resulting value. You can see that here and here for Assembly, and here for Module. I think it should be safe to just cache those results in a shared static dict. As far as I'm aware, this shouldn't get too bloated. If there is some chance of insane numbers of assemblies/modules, we could have it auto-clear at a certain number of items.

After these changes, ~93% of the remaining allocations in the CustomTiming ctor benchmark are from new StackTrace().GetFrames();.

Benchmarks!

Before:

|                                     Method |              Runtime | IncludeStackTrace |        Mean |     Error |    StdDev |  Gen 0 |  Gen 1 | Allocated |
|------------------------------------------- |--------------------- |------------------ |------------:|----------:|----------:|-------:|-------:|----------:|
|    'Creation of a standalone CustomTiming' |             .NET 5.0 |             False |    176.2 ns |   1.47 ns |   1.38 ns | 0.0200 |      - |     176 B |
| 'Creation a CustomTiming via MiniProfiler' |             .NET 5.0 |             False |    353.2 ns |   6.99 ns |  14.90 ns | 0.0200 |      - |     197 B |
|   'Using a CustomTiming with MiniProfiler' |             .NET 5.0 |             False |    400.6 ns |   7.69 ns |  13.67 ns | 0.0200 |      - |     197 B |
|    'Creation of a standalone CustomTiming' | .NET Framework 4.7.2 |             False |    224.9 ns |   1.22 ns |   1.08 ns | 0.0200 |      - |     177 B |
| 'Creation a CustomTiming via MiniProfiler' | .NET Framework 4.7.2 |             False |    429.1 ns |   8.59 ns |  12.59 ns | 0.0200 |      - |     198 B |
|   'Using a CustomTiming with MiniProfiler' | .NET Framework 4.7.2 |             False |    506.3 ns |   9.56 ns |  13.72 ns | 0.0200 |      - |     198 B |
|    'Creation of a standalone CustomTiming' |             .NET 5.0 |              True | 21,611.5 ns | 105.82 ns |  98.99 ns | 2.5400 | 0.0200 |  16,016 B |
| 'Creation a CustomTiming via MiniProfiler' |             .NET 5.0 |              True | 23,946.8 ns | 472.94 ns | 614.95 ns | 2.7600 | 0.8600 |  17,366 B |
|   'Using a CustomTiming with MiniProfiler' |             .NET 5.0 |              True | 23,322.4 ns | 151.49 ns | 134.29 ns | 2.7600 | 0.8200 |  17,366 B |
|    'Creation of a standalone CustomTiming' | .NET Framework 4.7.2 |              True | 24,639.7 ns | 163.74 ns | 153.16 ns | 4.0600 | 0.0200 |  25,644 B |
| 'Creation a CustomTiming via MiniProfiler' | .NET Framework 4.7.2 |              True | 27,200.9 ns | 188.39 ns | 147.08 ns | 4.4000 | 1.0000 |  27,823 B |
|   'Using a CustomTiming with MiniProfiler' | .NET Framework 4.7.2 |              True | 27,690.8 ns | 277.25 ns | 231.51 ns | 4.4000 | 1.0000 |  27,823 B |

|                  Method |              Runtime |           Mean |       Error |      StdDev |  Gen 0 | Allocated |
|------------------------ |--------------------- |---------------:|------------:|------------:|-------:|----------:|
| StackTraceSnippet.Get() |             .NET 5.0 | 19,836.3584 ns | 350.0249 ns | 310.2879 ns | 2.2583 |  14,328 B |
| StackTraceSnippet.Get() | .NET Framework 4.7.2 | 22,316.2177 ns | 331.9256 ns | 310.4834 ns | 3.3875 |  21,359 B |

After:

|                                     Method |              Runtime | IncludeStackTrace |        Mean |     Error |    StdDev |  Gen 0 |  Gen 1 | Allocated |
|------------------------------------------- |--------------------- |------------------ |------------:|----------:|----------:|-------:|-------:|----------:|
|    'Creation of a standalone CustomTiming' |             .NET 5.0 |             False |    180.2 ns |   1.38 ns |   1.22 ns | 0.0200 |      - |     176 B |
| 'Creation a CustomTiming via MiniProfiler' |             .NET 5.0 |             False |    345.0 ns |   6.84 ns |  12.16 ns | 0.0200 |      - |     197 B |
|   'Using a CustomTiming with MiniProfiler' |             .NET 5.0 |             False |    384.8 ns |   7.61 ns |  13.91 ns | 0.0200 |      - |     197 B |
|    'Creation of a standalone CustomTiming' | .NET Framework 4.7.2 |             False |    224.8 ns |   1.35 ns |   1.26 ns | 0.0200 |      - |     177 B |
| 'Creation a CustomTiming via MiniProfiler' | .NET Framework 4.7.2 |             False |    429.4 ns |   8.59 ns |  13.38 ns | 0.0200 |      - |     198 B |
|   'Using a CustomTiming with MiniProfiler' | .NET Framework 4.7.2 |             False |    502.2 ns |  10.04 ns |  12.33 ns | 0.0200 |      - |     198 B |
|    'Creation of a standalone CustomTiming' |             .NET 5.0 |              True | 10,296.4 ns |  57.20 ns |  53.51 ns | 0.7800 |      - |   4,920 B |
| 'Creation a CustomTiming via MiniProfiler' |             .NET 5.0 |              True | 11,682.6 ns |  95.54 ns |  84.69 ns | 0.8200 | 0.2000 |   5,174 B |
|   'Using a CustomTiming with MiniProfiler' |             .NET 5.0 |              True | 12,106.2 ns | 104.07 ns |  97.35 ns | 0.8200 | 0.2000 |   5,174 B |
|    'Creation of a standalone CustomTiming' | .NET Framework 4.7.2 |              True | 12,379.3 ns | 183.14 ns | 162.35 ns | 1.2000 |      - |   7,647 B |
| 'Creation a CustomTiming via MiniProfiler' | .NET Framework 4.7.2 |              True | 13,867.5 ns |  90.04 ns |  84.22 ns | 1.2600 | 0.2800 |   8,045 B |
|   'Using a CustomTiming with MiniProfiler' | .NET Framework 4.7.2 |              True | 13,934.5 ns |  62.13 ns |  55.07 ns | 1.2600 | 0.2800 |   8,045 B |

|                  Method |              Runtime |           Mean |      Error |     StdDev |         Median |  Gen 0 | Allocated |
|------------------------ |--------------------- |---------------:|-----------:|-----------:|---------------:|-------:|----------:|
| StackTraceSnippet.Get() |             .NET 5.0 |  8,965.8762 ns | 57.2045 ns | 50.7103 ns |  8,954.6860 ns | 0.6714 |   4,232 B |
| StackTraceSnippet.Get() | .NET Framework 4.7.2 | 10,543.8782 ns | 60.1173 ns | 56.2337 ns | 10,553.3630 ns | 1.0529 |   6,644 B |

benbryant0 added 5 commits May 6, 2022 20:31
@benbryant0
Remove RuntimeIdentifier
a90147c 
This creates a self-contained executable, which BDN doesn't seem to support
@benbryant0
Remove commented test code
196f015
@benbryant0
Set up profiler per iteration
bc7f293 
If the benchmark is fast enough BDN will run enough operations per iteration that the accumulated CustomTimings will eat all memory.
@benbryant0
Bench with stack trace vs without
5a7a8f5
@benbryant0
Cache assembly & module names
ccd5613 
These are not (currently) cached in any meaningful way. Type & MethodInfo don't have the same problem.
NickCraver
NickCraver approved these changes May 28, 2022
View reviewed changes
Copy link
Member
@NickCraver NickCraver left a comment

Choose a reason for hiding this comment

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

This is looking awesome - thank you! I want to further visit this with ValueStringBuilder just limited on time. The improvements are much appreciated :)

@NickCraver NickCraver merged commit ce90f40 into MiniProfiler:main May 28, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@NickCraver NickCraver NickCraver approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@benbryant0 @NickCraver
0