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

Optimise StackTraceSnippet.Get #605

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

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 |

This creates a self-contained executable, which BDN doesn't seem to support
If the benchmark is fast enough BDN will run enough operations per iteration that the accumulated CustomTimings will eat all memory.
These are not (currently) cached in any meaningful way. Type & MethodInfo don't have the same problem.
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
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants