These results are quite odd to me… I would have expected the number of allocations with the second patch to be lower than without it, and the first patch to be potentially slower than the second one (due to more sql queries) but with much fewer allocations (since we don’t load the records to memory at all).
Any chance you could rerun these tests to make sure the results are consistent?
Yep, repeating is not a big problem (started from 2nd patch to unpatched to 1st patch)
# Unpatched
2021-12-06T17:54:15 [I|app|6376b5d2] Completed 200 OK in 513ms (Views: 364.7ms | ActiveRecord: 83.2ms | Allocations: 214750)
2021-12-06T17:54:27 [I|app|5462c21a] Completed 200 OK in 504ms (Views: 354.2ms | ActiveRecord: 82.4ms | Allocations: 214762)
2021-12-06T17:54:57 [I|app|f03eb87a] Completed 200 OK in 518ms (Views: 367.2ms | ActiveRecord: 80.4ms | Allocations: 214788)
2021-12-06T17:55:03 [I|app|d742dd89] Completed 200 OK in 393ms (Views: 293.3ms | ActiveRecord: 45.6ms | Allocations: 195138)
2021-12-06T17:55:09 [I|app|9cd22706] Completed 200 OK in 386ms (Views: 286.0ms | ActiveRecord: 51.6ms | Allocations: 195127)
2021-12-06T17:55:14 [I|app|983b8b32] Completed 200 OK in 412ms (Views: 311.6ms | ActiveRecord: 51.7ms | Allocations: 195051)
2021-12-06T17:55:22 [I|app|41eab8c8] Completed 200 OK in 613ms (Views: 447.5ms | ActiveRecord: 50.2ms | Allocations: 195062)
2021-12-06T17:55:31 [I|app|8e0d820a] Completed 200 OK in 394ms (Views: 296.0ms | ActiveRecord: 49.2ms | Allocations: 195058)
2021-12-06T17:55:38 [I|app|ca711123] Completed 200 OK in 399ms (Views: 293.9ms | ActiveRecord: 51.0ms | Allocations: 195034)
2021-12-06T17:56:14 [I|app|4e738319] Completed 200 OK in 554ms (Views: 362.4ms | ActiveRecord: 88.1ms | Allocations: 225748)
2021-12-06T17:57:50 [I|app|07cb9993] Completed 200 OK in 390ms (Views: 298.5ms | ActiveRecord: 42.9ms | Allocations: 198071)
2021-12-06T17:58:04 [I|app|f661dbc1] Completed 200 OK in 464ms (Views: 373.5ms | ActiveRecord: 41.3ms | Allocations: 195021)
2021-12-06T17:58:08 [I|app|b11ae57d] Completed 200 OK in 484ms (Views: 358.7ms | ActiveRecord: 55.1ms | Allocations: 214787)
2021-12-06T17:58:14 [I|app|c9d9ccb4] Completed 200 OK in 510ms (Views: 362.7ms | ActiveRecord: 49.2ms | Allocations: 195018)
2021-12-06T17:58:18 [I|app|280b1b81] Completed 200 OK in 379ms (Views: 285.8ms | ActiveRecord: 48.3ms | Allocations: 195125)
2021-12-06T17:58:29 [I|app|5486e1fc] Completed 200 OK in 382ms (Views: 291.5ms | ActiveRecord: 42.2ms | Allocations: 195048)
2021-12-06T17:58:38 [I|app|5e0a2d10] Completed 200 OK in 354ms (Views: 266.6ms | ActiveRecord: 39.4ms | Allocations: 195044)
# 1st patch
2021-12-06T18:04:16 [I|app|d97156a6] Completed 200 OK in 881ms (Views: 621.7ms | ActiveRecord: 136.6ms | Allocations: 426358)
2021-12-06T18:04:24 [I|app|2f273c78] Completed 200 OK in 678ms (Views: 523.7ms | ActiveRecord: 102.7ms | Allocations: 364450)
2021-12-06T18:04:30 [I|app|b54b9d5d] Completed 200 OK in 715ms (Views: 548.7ms | ActiveRecord: 104.6ms | Allocations: 364400)
2021-12-06T18:04:37 [I|app|9fcf17ab] Completed 200 OK in 830ms (Views: 621.6ms | ActiveRecord: 119.5ms | Allocations: 364373)
2021-12-06T18:04:49 [I|app|d99491c3] Completed 200 OK in 674ms (Views: 509.3ms | ActiveRecord: 115.0ms | Allocations: 371840)
2021-12-06T18:05:11 [I|app|5e70732d] Completed 200 OK in 785ms (Views: 603.0ms | ActiveRecord: 114.0ms | Allocations: 384170)
2021-12-06T18:05:23 [I|app|b77eb40b] Completed 200 OK in 810ms (Views: 605.9ms | ActiveRecord: 121.7ms | Allocations: 384147)
2021-12-06T18:05:33 [I|app|67f07e6a] Completed 200 OK in 652ms (Views: 509.9ms | ActiveRecord: 93.1ms | Allocations: 364453)
2021-12-06T18:05:48 [I|app|1ba038b4] Completed 200 OK in 807ms (Views: 628.4ms | ActiveRecord: 111.3ms | Allocations: 384157)
2021-12-06T18:06:01 [I|app|07e655d9] Completed 200 OK in 713ms (Views: 545.8ms | ActiveRecord: 104.0ms | Allocations: 364357)
2021-12-06T18:06:09 [I|app|8f0e296e] Completed 200 OK in 664ms (Views: 512.5ms | ActiveRecord: 104.0ms | Allocations: 364431)
2021-12-06T18:06:14 [I|app|c8aa5509] Completed 200 OK in 834ms (Views: 654.3ms | ActiveRecord: 95.7ms | Allocations: 364384)
2021-12-06T18:06:19 [I|app|56a20e5d] Completed 200 OK in 654ms (Views: 507.3ms | ActiveRecord: 99.8ms | Allocations: 364351)
2021-12-06T18:06:24 [I|app|1c9ef0f7] Completed 200 OK in 716ms (Views: 557.0ms | ActiveRecord: 112.2ms | Allocations: 364392)
2021-12-06T18:06:28 [I|app|205da9eb] Completed 200 OK in 827ms (Views: 625.3ms | ActiveRecord: 118.6ms | Allocations: 364379)
2021-12-06T18:06:44 [I|app|dcea35c0] Completed 200 OK in 639ms (Views: 499.1ms | ActiveRecord: 93.0ms | Allocations: 364371)
2021-12-06T18:09:24 [I|app|4870095a] Completed 200 OK in 815ms (Views: 604.3ms | ActiveRecord: 133.4ms | Allocations: 387556)
2021-12-06T18:09:28 [I|app|f54faaff] Completed 200 OK in 707ms (Views: 517.6ms | ActiveRecord: 141.3ms | Allocations: 364451)
# 2nd patch
2021-12-06T17:37:57 [I|app|7be42e83] Completed 200 OK in 480ms (Views: 267.6ms | ActiveRecord: 87.1ms | Allocations: 214113)
2021-12-06T17:38:04 [I|app|81ba7632] Completed 200 OK in 383ms (Views: 247.1ms | ActiveRecord: 88.4ms | Allocations: 190524)
2021-12-06T17:38:13 [I|app|71623dba] Completed 200 OK in 388ms (Views: 252.9ms | ActiveRecord: 83.8ms | Allocations: 191574)
2021-12-06T17:38:52 [I|app|bac5eae2] Completed 200 OK in 343ms (Views: 244.4ms | ActiveRecord: 49.0ms | Allocations: 190525)
2021-12-06T17:44:53 [I|app|f3c8b266] Completed 200 OK in 377ms (Views: 233.0ms | ActiveRecord: 82.7ms | Allocations: 194378)
2021-12-06T17:45:00 [I|app|431cfb26] Completed 200 OK in 416ms (Views: 277.8ms | ActiveRecord: 81.2ms | Allocations: 210239)
2021-12-06T17:45:05 [I|app|05c421b1] Completed 200 OK in 379ms (Views: 249.0ms | ActiveRecord: 81.0ms | Allocations: 190504)
2021-12-06T17:45:22 [I|app|36075764] Completed 200 OK in 327ms (Views: 231.4ms | ActiveRecord: 48.8ms | Allocations: 190408)
2021-12-06T17:45:36 [I|app|324672ba] Completed 200 OK in 328ms (Views: 230.3ms | ActiveRecord: 49.0ms | Allocations: 190410)
2021-12-06T17:45:51 [I|app|23b38785] Completed 200 OK in 311ms (Views: 216.4ms | ActiveRecord: 51.3ms | Allocations: 190405)
2021-12-06T17:48:15 [I|app|322d78f0] Completed 200 OK in 488ms (Views: 382.5ms | ActiveRecord: 51.2ms | Allocations: 190379)
2021-12-06T17:48:23 [I|app|4eb7681a] Completed 200 OK in 383ms (Views: 228.6ms | ActiveRecord: 47.2ms | Allocations: 190407)
2021-12-06T17:49:01 [I|app|74c6544d] Completed 200 OK in 339ms (Views: 241.9ms | ActiveRecord: 47.6ms | Allocations: 190427)
2021-12-06T17:49:07 [I|app|96f9f37f] Completed 200 OK in 569ms (Views: 457.4ms | ActiveRecord: 47.4ms | Allocations: 193853)
2021-12-06T17:49:15 [I|app|c9e79df5] Completed 200 OK in 320ms (Views: 223.8ms | ActiveRecord: 47.3ms | Allocations: 190411)
2021-12-06T17:50:49 [I|app|9a7431fd] Completed 200 OK in 343ms (Views: 239.4ms | ActiveRecord: 50.3ms | Allocations: 190415)
2021-12-06T17:52:10 [I|app|f86736a8] Completed 200 OK in 315ms (Views: 218.2ms | ActiveRecord: 49.6ms | Allocations: 190379)
2021-12-06T17:52:16 [I|app|8559e10f] Completed 200 OK in 391ms (Views: 255.1ms | ActiveRecord: 80.2ms | Allocations: 190573)
2021-12-06T17:52:21 [I|app|e96056b9] Completed 200 OK in 343ms (Views: 245.6ms | ActiveRecord: 47.3ms | Allocations: 190397)
I have used the following test method:
- Impersonate a normal user
- Apply patch/keep unpatched version
- 1st and 2nd patch refer to the patches from this thread, not from the pull request on GH
- Restart Foreman via systemctl restart foreman.service
- Reload https://foreman.desy.de/hosts?per_page=100 in browser via ctrl+r
Seems like I was a bit too quick earlier, especially the first queries after the restart seems to be slower.
Thanks @stdietrich this is great data!
I generated a quick average and median of the measurements:
| Measure | Case | Value |
|---|---|---|
| Average - Total | 1st patch | 744.5 |
| 2nd patch | 380.2 | |
| Unpatched | 449.9 | |
| Average - views | 1st patch | 566.4 |
| 2nd patch | 260.1 | |
| Unpatched | 330.2 | |
| Average - AR | 1st patch | 112.3 |
| 2nd patch | 61.6 | |
| Unpatched | 56.0 | |
| Average - allocations | 1st patch | 372834.4 |
| 2nd patch | 193174.8 | |
| Unpatched | 201684.2 | |
| Median - Total | 1st patch | 715.5 |
| 2nd patch | 377.0 | |
| Unpatched | 412.0 | |
| Median - views | 1st patch | 552.9 |
| 2nd patch | 244.4 | |
| Unpatched | 311.6 | |
| Median - AR | 1st patch | 111.8 |
| 2nd patch | 50.3 | |
| Unpatched | 50.2 | |
| Median - allocations | 1st patch | 364440.5 |
| 2nd patch | 190427.0 | |
| Unpatched | 195125.0 |
Looks like there are some negative affects of the first patch on the index page, we should look deeper into where they come from.
1 Like
Just to follow up here as well: @stdietrich - thanks to your detailed report and assistance, we have decided to go with the 2nd patch which always leads to an improved performance. In addition, I have identified the specific code path that leads to loading all config reports to memory in the overview and modified it so that it does not attempt to use the authorization cache, which should resolve the slowness you have observed on the overview pane as well. You can see the full details on the PR, though I’m not sure if it will apply cleanly on 2.5.4.
2 Likes
I could apply the PR minus the tests without any issues on 2.5.4. It works, the memory issue is gone and overview table loads quickly.
Once it’s merged, I hope it will be included in a 3.1.x release.
Thanks @tbrisker for the help and patch!
3 Likes
Thanks, if you could take a look in the production.log in the upcoming days and look for this message:
Loaded #{collection.size} #{subject.class} records into authorization cache for permission #{permission}, consider skipping caching for this check
If you spot anything, let us know. There might be other places where we load too much data into the cache.