Content View list takes too long

Bernhard_Suttner · January 19, 2024, 2:07pm

=> from 274 hosts. One query for each host. Is this the cause of the issue? Can this be optimized?

They are interesting, too:

@gvde can you share the section of the production.log from the content vie request - like:

2024-01-19T14:57:39 [I|app|a53472dd] Completed 200 OK in 39ms (Views: 0.3ms | ActiveRecord: 1.4ms | Allocations: 4781)

The interesting part is "200 OK in 39ms (Views: 0.3ms | ActiveRecord: 1.4ms | Allocations: 4781)

gvde · January 19, 2024, 2:31pm

I don’t think they are related to the number of hosts. It’s probably more a coincidence. Those queries look like this:

2024-01-19 07:07:00 CET LOG:  execute a19: SELECT "katello_root_repositories".* FROM "katello_root_repositories" WHERE "katello_root_repositories"."id" = $1 LIMIT $2
2024-01-19 07:07:00 CET DETAIL:  parameters: $1 = '273', $2 = '1'
2024-01-19 07:07:00 CET LOG:  execute a19: SELECT "katello_root_repositories".* FROM "katello_root_repositories" WHERE "katello_root_repositories"."id" = $1 LIMIT $2
2024-01-19 07:07:00 CET DETAIL:  parameters: $1 = '260', $2 = '1'
2024-01-19 07:07:00 CET LOG:  execute a19: SELECT "katello_root_repositories".* FROM "katello_root_repositories" WHERE "katello_root_repositories"."id" = $1 LIMIT $2
2024-01-19 07:07:00 CET DETAIL:  parameters: $1 = '261', $2 = '1'
2024-01-19 07:07:00 CET LOG:  execute a19: SELECT "katello_root_repositories".* FROM "katello_root_repositories" WHERE "katello_root_repositories"."id" = $1 LIMIT $2
2024-01-19 07:07:00 CET DETAIL:  parameters: $1 = '262', $2 = '1'

This is the log for that API call:

2024-01-19T07:06:56 [I|app|1d06ae36] Started GET "/katello/api/v2/content_views?organization_id=1&nondefault=true&include_permissions=true&sort_by=name&sort_order=asc&per_page=20&page=1" for 136.172.15.242 at 2024-01-19 07:06:56 +0100
2024-01-19T07:06:56 [I|app|1d06ae36] Processing by Katello::Api::V2::ContentViewsController#index as HTML
2024-01-19T07:06:56 [I|app|1d06ae36]   Parameters: {"organization_id"=>"1", "nondefault"=>"true", "include_permissions"=>"true", "sort_by"=>"name", "sort_order"=>"asc", "per_page"=>"20", "page"=>"1", "api_version"=>"v2"}
2024-01-19T07:07:22 [I|app|1d06ae36]   Rendered /usr/share/gems/gems/katello-4.10.0/app/views/katello/api/v2/content_views/index.json.rabl within katello/api/v2/layouts/collection (Duration: 25925.0ms | Allocations: 19752539)
2024-01-19T07:07:22 [I|app|1d06ae36]   Rendered layout /usr/share/gems/gems/katello-4.10.0/app/views/katello/api/v2/layouts/collection.json.erb (Duration: 25927.4ms | Allocations: 19755118)
2024-01-19T07:07:22 [I|app|1d06ae36] Completed 200 OK in 25941ms (Views: 25306.9ms | ActiveRecord: 625.5ms | Allocations: 19759206)

jeremylenz · January 19, 2024, 3:27pm

Can you expand on this? What do you mean by “hosts hangs?”

lumarel · January 19, 2024, 3:34pm

Ah oh sorry I just meant the majority are assigned to 4 CVs.

Bernhard_Suttner · January 22, 2024, 8:59am

Have a look at UI Performance improvements for foreman / katello - 19 million allocations is a pretty high number…

I will try to have a look at your API request later on and try to analyze the send SQL queries.

mindo · January 22, 2024, 11:56am

Curl output:

real    4m1.385s 
user    0m0.037s
sys     0m0.023s

Distribution of hosts per CV:

      1 Library/AlmaLinux8
      1 Library/CentOS7_BareOS_Subscription
      1 Library/OracleLinux7
      1 Library/RockyLinux8_BareOS_Subscription
      3 Library/CentOS7_SCL_MariaDB_10
      4 Library/Centos_7_MariaDB_10
      7 Library/AmazonLinux2
      7 Library/OracleLinux8
     15 Library/Centos_7_EDS_Openstack_Train
     19 Library/CentOS_8
     83 Library/RockyLinux9
    274 Library/RockyLinux8
    337 Library/CentOS7_SCL

I don’t think the number of hosts/content views is really the issue, because when we upgraded from foreman 3.6 to 3.7 we noticed this slowness. Reverting to the machines’ snapshots to before the upgrade and the performance was restored. It was still slow, but it was on the order of tens of seconds and not several minutes.

Bernhard_Suttner · January 24, 2024, 11:39am

Just found out this:

[root@or ~]# grep SELECT /tmp/cv_sql | grep -v CACHE | grep -v taxono | grep katello_activation_keys 
2024-01-22T16:37:04 [D|sql|680d2987]   Katello::ActivationKey Load (1.1ms)  SELECT "katello_activation_keys".* FROM "katello_activation_keys" WHERE "katello_activation_keys"."content_view_id" IN ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15)  [["content_view_id", 37], ["content_view_id", 4], ["content_view_id", 19], ["content_view_id", 35], ["content_view_id", 5], ["content_view_id", 34], ["content_view_id", 29], ["content_view_id", 16], ["content_view_id", 20], ["content_view_id", 11], ["content_view_id", 18], ["content_view_id", 25], ["content_view_id", 36], ["content_view_id", 23], ["content_view_id", 14]]
2024-01-22T16:37:04 [D|sql|680d2987]    (0.2ms)  SELECT "katello_activation_keys"."id" FROM "katello_activation_keys" WHERE "katello_activation_keys"."content_view_id" = $1 AND "katello_activation_keys"."environment_id" = $2  [["content_view_id", 37], ["environment_id", 4]]
2024-01-22T16:37:04 [D|sql|680d2987]    (0.2ms)  SELECT "katello_activation_keys"."id" FROM "katello_activation_keys" WHERE "katello_activation_keys"."content_view_id" = $1 AND "katello_activation_keys"."environment_id" = $2  [["content_view_id", 37], ["environment_id", 3]]
[.....]

Similar for content_view_versions:

2024-01-22T16:37:04 [D|sql|680d2987]   Katello::ContentViewVersion Load (0.9ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" IN ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15)  [["content_view_id", 37], ["content_view_id", 4], ["content_view_id", 19], ["content_view_id", 35], ["content_view_id", 5], ["content_view_id", 34], ["content_view_id", 29], ["content_view_id", 16], ["content_view_id", 20], ["content_view_id", 11], ["content_view_id", 18], ["content_view_id", 25], ["content_view_id", 36], ["content_view_id", 23], ["content_view_id", 14]]
2024-01-22T16:37:04 [D|sql|680d2987]    (0.4ms)  SELECT COUNT(*) FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1  [["content_view_id", 37]]
2024-01-22T16:37:04 [D|sql|680d2987]   Katello::ContentViewVersion Load (0.3ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 37], ["LIMIT", 1]]
2024-01-22T16:37:04 [D|sql|680d2987]   Katello::ContentViewHistory Load (0.3ms)  SELECT "katello_content_view_histories".* FROM "katello_content_view_histories" INNER JOIN "katello_content_view_versions" ON "katello_content_view_versions"."id" = "katello_content_view_histories"."katello_content_view_version_id" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY "katello_content_view_histories"."created_at" DESC LIMIT $2  [["content_view_id", 37], ["LIMIT", 1]]
[.....]

Maybe something to optimize, but pretty sure not the root cause for the issue.

Bernhard_Suttner · January 24, 2024, 1:29pm

Another pretty strange one if the content_views index page is viewed:

2024-01-24T14:20:59 [D|sql|daf7ec59]   Katello::ContentViewVersion Load (0.6ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" IN ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15, $16, $17, $18, $19, $20)  [["content_view_id", 3], ["content_view_id", 4], ["content_view_id", 5], ["content_view_id", 6], ["content_view_id", 7], ["content_view_id", 8], ["content_view_id", 9], ["content_view_id", 10], ["content_view_id", 11], ["content_view_id", 12], ["content_view_id", 13], ["content_view_id", 14], ["content_view_id", 15], ["content_view_id", 16], ["content_view_id", 17], ["content_view_id", 18], ["content_view_id", 19], ["content_view_id", 20], ["content_view_id", 21], ["content_view_id", 22]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   Katello::ContentViewVersion Load (0.3ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   CACHE Katello::ContentViewVersion Load (0.0ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY major DESC, minor DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   Katello::ContentViewVersion Load (0.3ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY created_at DESC  [["content_view_id", 17]]
2024-01-24T14:21:00 [D|sql|daf7ec59]   Katello::ContentViewVersion Load (0.2ms)  SELECT "katello_content_view_versions".* FROM "katello_content_view_versions" WHERE "katello_content_view_versions"."content_view_id" = $1 ORDER BY "katello_content_view_versions"."created_at" DESC LIMIT $2  [["content_view_id", 17], ["LIMIT", 1]]

Why are there 27 SQL queries for the same? OK, they are cached but…

jeremylenz · January 24, 2024, 3:51pm

Here is the rabl file that builds the API response for the content views index: https://github.com/Katello/katello/blob/master/app/views/katello/api/v2/content_views/base.json.rabl

You can assume that everywhere you see a dot (.) it’s doing a new query and building a json node from that data. Note that that file runs once for each displayed content view on the page.

I’ve been tinkering with leaving out certain parts of the response, but I haven’t found any ‘low-hanging fruit’ yet - if I comment out 50% of the nodes, it loads 50% faster. If I comment out 25% of the nodes, it loads 25% faster. I’m not quite sure where to go from here…

Bernhard_Suttner · January 24, 2024, 4:09pm

We have just talked internally about this and trying to find solutions to improve it.

in case we would define a completely new implementation, I would expect

access to /index should only load the most important data which is e.g. necessary on the API and on the page
access to a specific content view version loads all data

Currently, base.json.rabl has nearly all data - which is accessible for index and for show. This shoud be differ.

Additionally, I would expect that the controller “loads” all the data and the view does not load additionally data - it just displays what was already loaded.

For Content Views / Products this is “just” a small performance issue, but think about moving the hosts page to react by using the API. This would be a no-go with the current approach.

jeremylenz · January 24, 2024, 4:14pm

Of course, this makes sense! The problem is that most of the data is actually used in the frontend rendering, and it’s very difficult to surmise what might not be needed, and also if it turns out we actually need most of it, then we won’t improve performance that much by removing the unused parts.

Bernhard_Suttner · January 24, 2024, 4:40pm

Isn’t this the job of the .includes in katello/app/controllers/katello/api/v2/content_views_controller.rb at master · Katello/katello · GitHub to make sure to load all the data and re-use it later on? (includes (ActiveRecord::QueryMethods) - APIdock)

Bernhard_Suttner · January 26, 2024, 1:05pm

If I load the content view page, I have 641 SELECT which access content_view_version (20 content views and only one version available for each content view). This is a lot.

After more analyzing, I found one HUGE issue which is pretty new in Katello:

attributes :needs_publish? => :needs_publish

This is responsible for 440 SQL queries.

Other areas can be improved, too.

Bernhard_Suttner · January 26, 2024, 1:40pm

I guess, its mainly because of katello/app/models/katello/content_view.rb at cc1b7cc0a624e00a6b59b5bae2be298a8ba6331e · Katello/katello · GitHub See Easy to Overlook Way to Break Eager Loading in Rails Apps

Bernhard_Suttner · January 26, 2024, 3:03pm

PR: Fixes #37109 - allow to use eager loading on latest_version_object by sbernhard · Pull Request #10865 · Katello/katello · GitHub

More to come soonish

mindo · January 29, 2024, 10:30am

Hello @Bernhard_Suttner ,

I just applied this patch and it’s like night and day, thank you for that

Before:

[PRD root@updates ~ - 09:47:55][0][0]# time hammer --no-headers content-view list --organization-label <my org> --fields "Content View ID" --noncomposite 1
Error: Timed out reading data from server

real    4m8.128s
user    0m1.546s
sys     0m0.265s

After:

[PRD root@updates ~ - 10:15:36][3][0]# time hammer --no-headers content-view list --organization-label <mt org> --fields "Content View ID" --noncomposite 1
(list of ids)

real    0m11.750s
user    0m1.585s
sys     0m0.208s

The web interface is also very fast.

The only downside I see is that on the web interface for the non composite CV the column Latest version has the message Not yet published

But hammer shows that info.

[PRD root@updates ~ - 10:28:01][3][0]# time hammer --no-headers content-view list --organization-label <my org> --fields "Content View ID,Last published" --noncomposite 1
33              | 2024/01/29 06:02:59
17              | 2024/01/29 06:00:20
3               | 2024/01/29 06:52:23
19              | 2024/01/29 06:01:39
(...)

Bernhard_Suttner · January 29, 2024, 10:46am

Still working on it. Thanks for you early feedback.

Bernhard_Suttner · January 29, 2024, 11:49am

Maybe you can try this commit which should fix the missing “Latest Version”:

Maybe its a little bit slower than the version you tried before.

mindo · January 29, 2024, 2:52pm

Yes, we just reverted the change on the file content_views_controller.rb and we can see again the Latest version info on the web interface.
As you predicted the load time went from little more than 10 seconds to over 2 minutes, so we’ll the change for now

Bernhard_Suttner · January 29, 2024, 3:25pm

Did you revert the change completely or did you use the latest version of Fixes #37109 - allow to use eager loading on latest_version_object by sbernhard · Pull Request #10865 · Katello/katello · GitHub ?