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.

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

[Performance] Startup regression #87235

Closed
sebastienros opened this issue Jun 7, 2023 · 11 comments · Fixed by #87240
Closed

[Performance] Startup regression #87235

sebastienros opened this issue Jun 7, 2023 · 11 comments · Fixed by #87240
Assignees
@tannergooding
Labels
area-CodeGen-coreclr CLR JIT compiler in src/coreclr/src/jit and related components such as SuperPMI tenet-performance Performance related issue
Milestone
8.0.0

Comments

@sebastienros
Copy link
Member

sebastienros commented Jun 7, 2023 •
edited
Loading

image

Smallest commits set:
fe98008...10222f9

Crank command lines:

crank --config https://raw.githubusercontent.com/aspnet/Benchmarks/main/scenarios/json.benchmarks.yml --config https://raw.githubusercontent.com/aspnet/Benchmarks/main/build/azure.profile.yml --config https://raw.githubusercontent.com/aspnet/Benchmarks/main/build/ci.profile.yml --scenario mapaction --profile intel-lin-app --profile intel-load2-load --application.framework net8.0 --application.collectDependencies true --application.options.collectCounters true --application.aspNetCoreVersion 8.0.0-preview.6.23302.1 --application.runtimeVersion 8.0.0-preview.6.23305.2 --application.sdkVersion 8.0.100-preview.6.23305.4

crank --config https://raw.githubusercontent.com/aspnet/Benchmarks/main/scenarios/json.benchmarks.yml --config https://raw.githubusercontent.com/aspnet/Benchmarks/main/build/azure.profile.yml --config https://raw.githubusercontent.com/aspnet/Benchmarks/main/build/ci.profile.yml --scenario mapaction --profile intel-lin-app --profile intel-load2-load --application.framework net8.0 --application.collectDependencies true --application.options.collectCounters true --application.aspNetCoreVersion 8.0.0-preview.6.23302.1 --application.runtimeVersion 8.0.0-preview.6.23306.5 --application.sdkVersion 8.0.100-preview.6.23305.4
@sebastienros sebastienros added the tenet-performance Performance related issue label Jun 7, 2023
@ghost ghost added the untriaged New issue has not been triaged by the area owner label Jun 7, 2023
@dotnet-issue-labeler dotnet-issue-labeler bot added the needs-area-label An area label is needed to ensure this gets routed to the appropriate area owners label Jun 7, 2023
@EgorBo
Copy link
Member

EgorBo commented Jun 7, 2023

Seems like arm64 is not affected

@sebastienros
Copy link
Member Author

@EgorBo you are correct, was checking and the last run is past the culprit build on these machines too.

@EgorBo
Copy link
Member

EgorBo commented Jun 7, 2023 •
edited
Loading

Methods jitted 3,644 --> 11,398 so something went wrong with R2R, perhaps, @jkotas can spot an offender
My guess is #85551 (cc @tannergooding)

| application                             | before                    | after                     |          |
| --------------------------------------- | ------------------------- | ------------------------- | -------- |
| CPU Usage (%)                           |                       100 |                        99 |   -1.00% |
| Cores usage (%)                         |                     2,794 |                     2,780 |   -0.50% |
| Working Set (MB)                        |                       464 |                       471 |   +1.51% |
| Private Memory (MB)                     |                     1,239 |                     1,248 |   +0.73% |
| Build Time (ms)                         |                     3,094 |                     3,083 |   -0.36% |
| Start Time (ms)                         |                       188 |                       403 | +114.36% |
| Published Size (KB)                     |                    90,772 |                    90,905 |   +0.15% |
| Symbols Size (KB)                       |                        21 |                        21 |    0.00% |
| .NET Core SDK Version                   | 8.0.100-preview.6.23305.4 | 8.0.100-preview.6.23305.4 |          |
| Max CPU Usage (%)                       |                       100 |                        99 |   -0.39% |
| Max Working Set (MB)                    |                       483 |                       498 |   +3.08% |
| Max GC Heap Size (MB)                   |                       341 |                       331 |   -3.03% |
| Size of committed memory by the GC (MB) |                       418 |                       431 |   +3.16% |
| Max Number of Gen 0 GCs / sec           |                      1.00 |                      1.00 |    0.00% |
| Max Number of Gen 1 GCs / sec           |                      1.00 |                      1.00 |    0.00% |
| Max Number of Gen 2 GCs / sec           |                      1.00 |                      1.00 |    0.00% |
| Max Time in GC (%)                      |                      1.00 |                      1.00 |    0.00% |
| Max Gen 0 Size (B)                      |                       584 |                       584 |    0.00% |
| Max Gen 1 Size (B)                      |                 4,045,344 |                 4,053,456 |   +0.20% |
| Max Gen 2 Size (B)                      |                 4,074,984 |                 4,022,064 |   -1.30% |
| Max LOH Size (B)                        |                   185,080 |                   381,744 | +106.26% |
| Max POH Size (B)                        |                 1,187,064 |                 1,187,064 |    0.00% |
| Max Allocation Rate (B/sec)             |               174,741,712 |               175,985,216 |   +0.71% |
| Max GC Heap Fragmentation               |                         1 |                         1 |   +1.23% |
| # of Assemblies Loaded                  |                        88 |                        88 |    0.00% |
| Max Exceptions (#/s)                    |                       452 |                       448 |   -0.88% |
| Max Lock Contention (#/s)               |                       110 |                       118 |   +7.27% |
| Max ThreadPool Threads Count            |                        48 |                        48 |    0.00% |
| Max ThreadPool Queue Length             |                       134 |                       139 |   +3.73% |
| Max ThreadPool Items (#/s)              |                 1,111,404 |                 1,121,252 |   +0.89% |
| Max Active Timers                       |                         1 |                         1 |    0.00% |
| IL Jitted (B)                           |                   366,349 |                   773,346 | +111.10% |
| Methods Jitted                          |                     3,634 |                    11,398 | +213.65% |


| load                   | before     | after      |         |
| ---------------------- | ---------- | ---------- | ------- |
| CPU Usage (%)          |         67 |         68 |  +1.49% |
| Cores usage (%)        |      1,877 |      1,903 |  +1.39% |
| Working Set (MB)       |         48 |         48 |   0.00% |
| Private Memory (MB)    |        358 |        358 |   0.00% |
| Start Time (ms)        |          0 |          0 |         |
| First Request (ms)     |        191 |        328 | +71.73% |
| Requests/sec           |    965,738 |    985,739 |  +2.07% |
| Requests               | 14,582,098 | 14,884,089 |  +2.07% |
| Mean latency (ms)      |       0.51 |       0.50 |  -1.12% |
| Max latency (ms)       |      50.18 |      36.19 | -27.88% |
| Bad responses          |          0 |          0 |         |
| Socket errors          |          0 |          0 |         |
| Read throughput (MB/s) |     199.86 |     204.00 |  +2.07% |
| Latency 50th (ms)      |       0.24 |       0.23 |  -2.08% |
| Latency 75th (ms)      |       0.28 |       0.27 |  -2.52% |
| Latency 90th (ms)      |       0.33 |       0.32 |  -2.45% |
| Latency 99th (ms)      |       9.41 |       9.51 |  +1.06% |

@tannergooding
Copy link
Member

Is there an easy way to get a list of functions that are now jitted that weren't before?

@tannergooding
Copy link
Member

I had done the r2rdump check for corelib as part of the PR and hadn't seen any differences; but maybe I had done something wrong here...

@EgorBo
Copy link
Member

EgorBo commented Jun 7, 2023

Is there an easy way to get a list of functions that are now jitted that weren't before?

--application.environmentVariables DOTNET_JitDisasmSummary=1 --application.options.displayOutput true

should do the trick

@jkotas jkotas added the area-CodeGen-coreclr CLR JIT compiler in src/coreclr/src/jit and related components such as SuperPMI label Jun 7, 2023
@ghost
Copy link

ghost commented Jun 7, 2023

Tagging subscribers to this area: @JulieLeeMSFT, @jakobbotsch
See info in area-owners.md if you want to be subscribed.

Issue Details

image

Smallest commits set:
fe98008...10222f9

Crank command lines:

crank --config https://raw.githubusercontent.com/aspnet/Benchmarks/main/scenarios/json.benchmarks.yml --config https://raw.githubusercontent.com/aspnet/Benchmarks/main/build/azure.profile.yml --config https://raw.githubusercontent.com/aspnet/Benchmarks/main/build/ci.profile.yml --scenario mapaction --profile intel-lin-app --profile intel-load2-load --application.framework net8.0 --application.collectDependencies true --application.options.collectCounters true --application.aspNetCoreVersion 8.0.0-preview.6.23302.1 --application.runtimeVersion 8.0.0-preview.6.23305.2 --application.sdkVersion 8.0.100-preview.6.23305.4

crank --config https://raw.githubusercontent.com/aspnet/Benchmarks/main/scenarios/json.benchmarks.yml --config https://raw.githubusercontent.com/aspnet/Benchmarks/main/build/azure.profile.yml --config https://raw.githubusercontent.com/aspnet/Benchmarks/main/build/ci.profile.yml --scenario mapaction --profile intel-lin-app --profile intel-load2-load --application.framework net8.0 --application.collectDependencies true --application.options.collectCounters true --application.aspNetCoreVersion 8.0.0-preview.6.23302.1 --application.runtimeVersion 8.0.0-preview.6.23306.5 --application.sdkVersion 8.0.100-preview.6.23305.4
Author: sebastienros
Assignees: -
Labels:

tenet-performance, area-CodeGen-coreclr, untriaged, needs-area-label
Milestone: -

@JulieLeeMSFT JulieLeeMSFT added this to the 8.0.0 milestone Jun 8, 2023
@ghost ghost removed the untriaged New issue has not been triaged by the area owner label Jun 8, 2023
@JulieLeeMSFT JulieLeeMSFT added untriaged New issue has not been triaged by the area owner and removed needs-area-label An area label is needed to ensure this gets routed to the appropriate area owners labels Jun 8, 2023
@ghost ghost removed the untriaged New issue has not been triaged by the area owner label Jun 8, 2023
@tannergooding tannergooding mentioned this issue Jun 8, 2023
Merged
@ghost ghost added the in-pr There is an active PR which will close this issue when it is merged label Jun 8, 2023
@EgorBo
Copy link
Member

EgorBo commented Jun 8, 2023 •
edited
Loading

I guess it makes sense to add a smoke test to dotnet/sdk to e.g. check number of entries in JitDisasmSummary for a hello word. E.g if we see, say, more than 100 (the ETW thing)t hen something went wrong

@ghost ghost removed the in-pr There is an active PR which will close this issue when it is merged label Jun 9, 2023
@tannergooding tannergooding reopened this Jun 9, 2023
@tannergooding
Copy link
Member

Not quite back to where we should be in the official runs:
image

@tannergooding
Copy link
Member

Looks like we're still jitting more methods than before. This looks to be because ASP.NET Core is using a crossgen2 version that has the issue. Once it pulls in an updated version of the SDK with the fix it should be resolved.

application baseline diff
CPU Usage (%) 99 99 0.00%
Cores usage (%) 2,781 2,770 -0.40%
Working Set (MB) 458 468 +2.18%
Private Memory (MB) 1,233 1,242 +0.73%
Build Time (ms) 3,446 6,121 +77.63%
Start Time (ms) 214 320 +49.53%
Published Size (KB) 90,772 91,037 +0.29%
Symbols Size (KB) 21 22 +4.76%
.NET Core SDK Version 8.0.100-preview.6.23305.4 8.0.100-preview.6.23308.7
Max CPU Usage (%) 99 100 +0.97%
Max Working Set (MB) 480 490 +2.16%
Max GC Heap Size (MB) 325 321 -1.40%
Size of committed memory by the GC (MB) 414 422 +1.81%
Max Number of Gen 0 GCs / sec 1.00 1.00 0.00%
Max Number of Gen 1 GCs / sec 1.00 1.00 0.00%
Max Number of Gen 2 GCs / sec 1.00 1.00 0.00%
Max Time in GC (%) 0.00 0.00
Max Gen 0 Size (B) 584 584 0.00%
Max Gen 1 Size (B) 4,041,864 4,048,776 +0.17%
Max Gen 2 Size (B) 3,996,016 4,036,208 +1.01%
Max LOH Size (B) 775,072 873,264 +12.67%
Max POH Size (B) 1,187,064 1,187,064 0.00%
Max Allocation Rate (B/sec) 173,551,248 176,208,664 +1.53%
Max GC Heap Fragmentation 1 1 +9.54%
# of Assemblies Loaded 88 93 +5.68%
Max Exceptions (#/s) 458 436 -4.80%
Max Lock Contention (#/s) 96 48 -50.00%
Max ThreadPool Threads Count 48 48 0.00%
Max ThreadPool Queue Length 199 160 -19.60%
Max ThreadPool Items (#/s) 1,105,618 1,123,343 +1.60%
Max Active Timers 1 1 0.00%
IL Jitted (B) 366,491 524,816 +43.20%
Methods Jitted 3,634 6,871 +89.08%
load baseline diff
CPU Usage (%) 67 68 +1.49%
Cores usage (%) 1,884 1,899 +0.80%
Working Set (MB) 48 48 0.00%
Private Memory (MB) 358 358 0.00%
Start Time (ms) 0 0
First Request (ms) 215 311 +44.65%
Requests/sec 974,651 974,338 -0.03%
Requests 14,716,749 14,711,973 -0.03%
Mean latency (ms) 0.44 0.47 +6.46%
Max latency (ms) 48.19 43.77 -9.17%
Bad responses 0 0
Socket errors 0 0
Read throughput (MB/s) 201.70 201.64 -0.03%
Latency 50th (ms) 0.24 0.24 -0.84%
Latency 75th (ms) 0.28 0.28 -0.36%
Latency 90th (ms) 0.32 0.32 +1.25%
Latency 99th (ms) 7.82 8.65 +10.61%

@tannergooding
Copy link
Member

It did indeed end up resolving after the update finished flowing around:
image

@ghost ghost locked as resolved and limited conversation to collaborators Jul 13, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@tannergooding tannergooding

Labels
area-CodeGen-coreclr CLR JIT compiler in src/coreclr/src/jit and related components such as SuperPMI tenet-performance Performance related issue
Projects
None yet
Milestone
8.0.0
Development

Successfully merging a pull request may close this issue.

Ensure that Vector<T> is tracked as "optimistic" for crossgen2 tannergooding/runtime
5 participants
@EgorBo @sebastienros @jkotas @tannergooding @JulieLeeMSFT