1.20.x / 3.1x : "All Hosts/Content Hosts" query bottle neck / slow request

Support
1

Problem:

Since ages ago (I found time to check it better just now) when I move to Hosts -> All Hosts/Content Hosts I’ve to wait at least 2/3 minutes to have the page.
In this installation (4vcpu and 20gb of ram) we’re running foreman with one organisation and 2 locations, ~120 virtual servers/VMWare RHEL with 8 VMWare hosts, DB engine Postgres.

Do you know how/what to check if there’s a bottle neck or some misconfiguration?
Is it a normal situation?

The other web requests are fine and fast.
Thanks

Expected outcome:

faster request

Foreman and Proxy versions:
Foreman 1.23.1
Katello 3.13.1

It was present also on 1.2x.x and Katello 3.1x

Foreman and Proxy plugin versions:

Distribution and version:

Other relevant data:
10.10.10.10 is my browser/pc

Hosts -> All Hosts request
When I start the web request-13:51:10:

2019-11-12T13:51:10 [I|app|18f67ecc] Started GET "/hosts" for 10.10.10.10 at 2019-11-12 13:51:10 +0000
2019-11-12T13:51:10 [I|app|18f67ecc] Processing by HostsController#index as HTML
2019-11-12T13:51:11 [I|app|18f67ecc]   Rendering hosts/index.html.erb within layouts/application

After 40/45 seconds-13:52:35:

2019-11-12T13:52:35 [I|app|18f67ecc]   Rendered common/_pagination.html.erb (2.8ms)
2019-11-12T13:52:35 [I|app|18f67ecc]   Rendered hosts/_list.html.erb (84185.2ms)
2019-11-12T13:52:35 [I|app|18f67ecc]   Rendered hosts/index.html.erb within layouts/application (84300.2ms)
2019-11-12T13:52:35 [I|app|18f67ecc]   Rendered common/_searchbar.html.erb (2.5ms)
2019-11-12T13:52:35 [I|app|18f67ecc]   Rendered layouts/_application_content.html.erb (8.8ms)
2019-11-12T13:52:35 [I|app|18f67ecc]   Rendering layouts/base.html.erb
2019-11-12T13:52:35 [I|app|18f67ecc]   Rendered layouts/base.html.erb (67.1ms)
2019-11-12T13:52:35 [I|app|18f67ecc] Completed 200 OK in 85921ms (Views: 66235.0ms | ActiveRecord: 19013.4ms)
2019-11-12T13:52:36 [I|app|3e03539b] Started GET "/hosts" for 10.10.10.10 at 2019-11-12 13:52:36 +0000
2019-11-12T13:52:36 [I|app|3e03539b] Processing by HostsController#index as HTML
2019-11-12T13:52:36 [I|app|3e03539b]   Rendering hosts/index.html.erb within layouts/application
2019-11-12T13:52:48 [I|app|cbc61d76] Started GET "/notification_recipients" for 10.10.10.10 at 2019-11-12 13:52:48 +0000
2019-11-12T13:52:48 [I|app|cbc61d76] Processing by NotificationRecipientsController#index as JSON
2019-11-12T13:52:48 [I|app|cbc61d76] Completed 200 OK in 15ms (Views: 0.3ms | ActiveRecord: 2.1ms)

After ~1 minutes-13:54:01:

2019-11-12T13:54:01 [I|app|3e03539b]   Rendered common/_pagination.html.erb (0.6ms)
2019-11-12T13:54:01 [I|app|3e03539b]   Rendered hosts/_list.html.erb (85145.6ms)
2019-11-12T13:54:01 [I|app|3e03539b]   Rendered hosts/index.html.erb within layouts/application (85167.5ms)
2019-11-12T13:54:01 [I|app|3e03539b]   Rendered common/_searchbar.html.erb (0.6ms)
2019-11-12T13:54:01 [I|app|3e03539b]   Rendered layouts/_application_content.html.erb (1.6ms)
2019-11-12T13:54:01 [I|app|3e03539b]   Rendering layouts/base.html.erb
2019-11-12T13:54:01 [I|app|3e03539b]   Rendered layouts/base.html.erb (32.1ms)
2019-11-12T13:54:01 [I|app|3e03539b] Completed 200 OK in 85870ms (Views: 69141.3ms | ActiveRecord: 16152.8ms)
2019-11-12T13:54:03 [I|app|49b0c5aa] Started GET "/api/v2/hosts/server1.mylan.net/power" for 10.10.10.10 at 2019-11-12 13:54:03 +0000
2019-11-12T13:54:03 [I|app|3332520d] Processing by Api::V2::HostsController#power_status as JSONN
2019-11-12T13:54:03 [I|app|49b0c5aa]   Parameters: {"apiv"=>"v2", "id"=>"server1.mylan.net"}
2019-11-12T13:54:04 [I|app|49b0c5aa] Completed 200 OK in 762ms (Views: 0.6ms | ActiveRecord: 14.8ms)
...and so on for the servers

and it finished after few seconds:

2019-11-12T13:54:15 [I|app|405daedd] Completed 200 OK in 433ms (Views: 0.6ms | ActiveRecord: 26.0ms)

And I can finally have the web page loaded.

Hosts -> Content Hosts request

2019-11-12T14:32:53 [I|app|748f3c54] Started GET "/content_hosts" for 10.10.10.10 at 2019-11-12 14:32:53 +0000
2019-11-12T14:32:53 [I|app|748f3c54] Processing by Bastion::BastionController#index as HTML
2019-11-12T14:32:53 [I|app|748f3c54]   Parameters: {"bastion_page"=>"content_hosts"}
2019-11-12T14:32:53 [I|app|748f3c54]   Rendering /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.13.1/engines/bastion/app/views/bastion/layouts/application.html.erb
2019-11-12T14:32:54 [I|app|748f3c54]   Rendering /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.13.1/engines/bastion/app/views/bastion/layouts/assets.html.erb
2019-11-12T14:32:54 [I|app|748f3c54]   Rendering layouts/base.html.erb
2019-11-12T14:32:54 [I|app|748f3c54]   Rendered layouts/base.html.erb (145.5ms)
2019-11-12T14:32:54 [I|app|748f3c54]   Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.13.1/engines/bastion/app/views/bastion/layouts/assets.html.erb (300.0ms)
2019-11-12T14:32:54 [I|app|748f3c54]   Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.13.1/engines/bastion/app/views/bastion/layouts/application.html.erb (315.5ms)
2019-11-12T14:32:54 [I|app|748f3c54] Completed 200 OK in 368ms (Views: 293.1ms | ActiveRecord: 44.9ms)
2019-11-12T14:32:54 [I|app|be57324c] Started GET "/content_hosts" for 10.10.10.10 at 2019-11-12 14:32:54 +0000
2019-11-12T14:32:54 [I|app|be57324c] Processing by Bastion::BastionController#index as HTML
2019-11-12T14:32:54 [I|app|be57324c]   Parameters: {"bastion_page"=>"content_hosts"}
2019-11-12T14:32:54 [I|app|be57324c]   Rendering /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.13.1/engines/bastion/app/views/bastion/layouts/application.html.erb
2019-11-12T14:32:54 [I|app|be57324c]   Rendering /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.13.1/engines/bastion/app/views/bastion/layouts/assets.html.erb
2019-11-12T14:32:54 [I|app|be57324c]   Rendering layouts/base.html.erb
2019-11-12T14:32:54 [I|app|be57324c]   Rendered layouts/base.html.erb (79.2ms)
2019-11-12T14:32:54 [I|app|be57324c]   Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.13.1/engines/bastion/app/views/bastion/layouts/assets.html.erb (154.1ms)
2019-11-12T14:32:54 [I|app|be57324c]   Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.13.1/engines/bastion/app/views/bastion/layouts/application.html.erb (165.6ms)
2019-11-12T14:32:54 [I|app|be57324c] Completed 200 OK in 200ms (Views: 167.7ms | ActiveRecord: 12.8ms)
2019-11-12T14:32:56 [I|app|632c8c7a] Started GET "/content-hosts/views/content-hosts.html" for 10.10.10.10 at 2019-11-12 14:32:56 +0000
2019-11-12T14:32:56 [I|app|f689b245] Started GET "/layouts/table-with-header.html" for 10.10.10.10 at 2019-11-12 14:32:56 +0000
2019-11-12T14:32:56 [I|app|cf264163] Started GET "/api/v2/hosts?organization_id=1&page=1&paged=true&per_page=100&search=&sort_by=name&sort_order=ASC" for 10.10.10.10 at 2019-11-12 14:32:56 +0000
2019-11-12T14:32:56 [I|app|cf264163] Processing by Api::V2::HostsController#index as JSON
2019-11-12T14:32:56 [I|app|cf264163]   Parameters: {"organization_id"=>"1", "page"=>"1", "paged"=>"true", "per_page"=>"100", "search"=>"", "sort_by"=>"name", "sort_order"=>"ASC", "apiv"=>"v2"}
2019-11-12T14:32:56 [I|app|7a6be019] Started GET "/notification_recipients" for 10.10.10.10 at 2019-11-12 14:32:56 +0000
2019-11-12T14:32:56 [I|app|7a6be019] Processing by NotificationRecipientsController#index as JSON
2019-11-12T14:32:56 [I|app|7a6be019] Completed 200 OK in 25ms (Views: 0.4ms | ActiveRecord: 2.6ms)
2019-11-12T14:32:56 [I|app|5d663546] Started GET "/layouts/partials/page-header-with-actions.html" for 10.10.10.10 at 2019-11-12 14:32:56 +0000
2019-11-12T14:32:56 [I|app|d218c1ba] Started GET "/layouts/partials/messages-container.html" for 10.10.10.10 at 2019-11-12 14:32:56 +0000
2019-11-12T14:32:56 [I|app|5b376b34] Started GET "/layouts/partials/table.html" for 10.10.10.10 at 2019-11-12 14:32:56 +0000
2019-11-12T14:32:56 [I|app|6ebeb6e8] Started GET "/common/views/select-action-dropdown.html" for 10.10.10.10 at 2019-11-12 14:32:56 +0000
2019-11-12T14:32:56 [I|app|df8718d8] Started GET "/layouts/select-all-results.html" for 10.10.10.10 at 2019-11-12 14:32:56 +0000
2019-11-12T14:32:57 [I|app|7041f6ac] Started GET "/api/v2/bookmarks?search=controller%3Dhosts" for 10.10.10.10 at 2019-11-12 14:32:57 +0000
2019-11-12T14:32:57 [I|app|7041f6ac] Processing by Api::V2::BookmarksController#index as JSON
2019-11-12T14:32:57 [I|app|7041f6ac]   Parameters: {"search"=>"controller=hosts", "apiv"=>"v2"}
2019-11-12T14:32:57 [I|app|7041f6ac]   Rendering api/v2/bookmarks/index.json.rabl within api/v2/layouts/index_layout
2019-11-12T14:32:57 [I|app|7041f6ac]   Rendered api/v2/bookmarks/index.json.rabl within api/v2/layouts/index_layout (8.2ms)
2019-11-12T14:32:57 [I|app|7041f6ac] Completed 200 OK in 27ms (Views: 12.6ms | ActiveRecord: 3.8ms)
2019-11-12T14:32:58 [I|app|cf264163]   Rendering api/v2/hosts/index.json.rabl within api/v2/layouts/index_layout

After 2 minutes:

2019-11-12T14:34:49 [I|app|cf264163]   Rendered api/v2/hosts/index.json.rabl within api/v2/layouts/index_layout (111076.7ms)
2019-11-12T14:34:49 [I|app|cf264163] Completed 200 OK in 112750ms (Views: 92875.6ms | ActiveRecord: 18449.9ms)
2019-11-12T14:34:54 [I|app|9b1543bc] Started GET "/errata/views/errata-counts.html" for 10.10.10.13 at 2019-11-12 14:34:54 +0000
2019-11-12T14:35:17 [I|app|008a067e] Started GET "/notification_recipients" for 10.10.10.13 at 2019-11-12 14:35:17 +0000
2019-11-12T14:35:17 [I|app|008a067e] Processing by NotificationRecipientsController#index as JSON
2019-11-12T14:35:17 [I|app|008a067e] Completed 200 OK in 20ms (Views: 0.4ms | ActiveRecord: 2.6ms)

And I can finally have the web page loaded.

2

I found the problem (maybe), I had more then 500K tasks stored into DB and I ran

foreman-rake foreman_tasks:cleanup TASK_SEARCH='label ~ *' AFTER='10d' VERBOSE=true

now just 30K tasks are present/stored and the “All Hosts” page will spend 10/20 seconds to be ready:

2019-11-13T09:24:59 [I|app|b021586d] Started GET "/hosts" for 10.10.10.10 at 2019-11-13 09:24:59 +0000
2019-11-13T09:24:59 [I|app|b021586d] Processing by HostsController#index as HTML
2019-11-13T09:25:00 [I|app|b021586d]   Rendering hosts/index.html.erb within layouts/application
2019-11-13T09:25:03 [I|app|8a49ca46] Started GET "/notification_recipients" for 10.10.10.10 at 2019-11-13 09:25:03 +0000
2019-11-13T09:25:03 [I|app|8a49ca46] Processing by NotificationRecipientsController#index as JSON
2019-11-13T09:25:03 [I|app|8a49ca46] Completed 200 OK in 13ms (Views: 0.2ms | ActiveRecord: 2.0ms)
2019-11-13T09:25:07 [I|app|b021586d]   Rendered common/_pagination.html.erb (1.2ms)
2019-11-13T09:25:07 [I|app|b021586d]   Rendered hosts/_list.html.erb (7259.9ms)
2019-11-13T09:25:07 [I|app|b021586d]   Rendered hosts/index.html.erb within layouts/application (7310.1ms)
2019-11-13T09:25:07 [I|app|b021586d]   Rendered common/_searchbar.html.erb (0.6ms)
2019-11-13T09:25:07 [I|app|b021586d]   Rendered layouts/_application_content.html.erb (1.7ms)
2019-11-13T09:25:07 [I|app|b021586d]   Rendering layouts/base.html.erb
2019-11-13T09:25:07 [I|app|b021586d]   Rendered layouts/base.html.erb (33.1ms)
2019-11-13T09:25:07 [I|app|b021586d] Completed 200 OK in 8551ms (Views: 6349.7ms | ActiveRecord: 1212.5ms)
2019-11-13T09:25:07 [I|app|d7f746e0] Started GET "/hosts" for 10.10.10.10 at 2019-11-13 09:25:07 +0000
2019-11-13T09:25:07 [I|app|d7f746e0] Processing by HostsController#index as HTML
2019-11-13T09:25:08 [I|app|d7f746e0]   Rendering hosts/index.html.erb within layouts/application
2019-11-13T09:25:13 [I|app|a95f6652] Started GET "/notification_recipients" for 10.10.10.10 at 2019-11-13 09:25:13 +0000
2019-11-13T09:25:13 [I|app|a95f6652] Processing by NotificationRecipientsController#index as JSON
2019-11-13T09:25:13 [I|app|a95f6652] Completed 200 OK in 9ms (Views: 0.2ms | ActiveRecord: 1.7ms)
2019-11-13T09:25:16 [I|app|d7f746e0]   Rendered common/_pagination.html.erb (0.6ms)
2019-11-13T09:25:16 [I|app|d7f746e0]   Rendered hosts/_list.html.erb (8166.7ms)
2019-11-13T09:25:16 [I|app|d7f746e0]   Rendered hosts/index.html.erb within layouts/application (8179.2ms)
2019-11-13T09:25:16 [I|app|d7f746e0]   Rendered common/_searchbar.html.erb (0.6ms)
2019-11-13T09:25:16 [I|app|d7f746e0]   Rendered layouts/_application_content.html.erb (1.5ms)
2019-11-13T09:25:16 [I|app|d7f746e0]   Rendering layouts/base.html.erb
2019-11-13T09:25:16 [I|app|d7f746e0]   Rendered layouts/base.html.erb (36.6ms)
2019-11-13T09:25:16 [I|app|d7f746e0] Completed 200 OK in 8915ms (Views: 7265.3ms | ActiveRecord: 1041.5ms)
2019-11-13T09:25:17 [I|app|76ed685a] Started GET "/notification_recipients" for 10.10.10.10 at 2019-11-13 09:25:17 +0000
2019-11-13T09:25:17 [I|app|becbb913] Started GET "/api/v2/hosts/server1.mylan.net/power" for 10.10.10.10 at 2019-11-13 09:25:17 +0000
2019-11-13T09:25:17 [I|app|becbb913] Processing by Api::V2::HostsController#power_status as JSON
2019-11-13T09:25:17 [I|app|becbb913]   Parameters: {"apiv"=>"v2", "id"=>"server1.mylan.net"}
....
2019-11-13T09:25:17 [I|app|76ed685a] Completed 200 OK in 19ms (Views: 0.5ms | ActiveRecord: 3.0ms)
....
2019-11-13T09:25:23 [I|app|e02f6d04] Completed 200 OK in 279ms (Views: 0.3ms | ActiveRecord: 4.3ms)

Besides running a cron job for the cleanup, there is another best practice?

1 Like
3

Hi,

as described in the readme of foreman-tasks, you can setup an automatic cleanup via configration.
As a reference, here is our production config that works perfectly fine for our ~1700 current managed hosts:

:foreman-tasks:
#  :cleanup:
#    :after: "30d"
#
# Logging configuration can be changed by uncommenting the loggers
# section and the logger configuration desired.
#
#   :loggers:
#     :dynflow:
#       :enabled: true
#     :action:
#       :enabled: true
# Cleaning configuration: how long should the actions be kept before deleted
# by `rake foreman_tasks:clean` task
#
  :cleanup:
#
# the period after which to delete all the tasks (by default all tasks are not being deleted after some period)
#
    :after: 30d
#
# per action settings to override the default defined in the actions (self.cleanup_after method)
#
    :actions:
      - :name: Actions::Katello::ContentView::Update
        :after: 7d
      - :name: Actions::Katello::ContentView::CapsuleGenerateAndSync
        :after: 7d
      - :name: Actions::Katello::ContentView::Publish
        :after: 7d
      - :name: Actions::Katello::Host::UploadPackageProfile
        :after: 7d
      - :name: Actions::Katello::Host::GenerateApplicability
        :after: 7d
      - :name: Actions::Katello::Repository::CapsuleGenerateAndSync
        :after: 7d
      - :name: Actions::Katello::Repository::Sync
        :after: 7d
      - :name: Actions::Katello::Host::Hypervisors
        :after: 1d

I’m a little surprised that a huge number of tasks in the db cause the content-hosts page to load slowly (ours loads in about 5-10 seconds on Foreman 1.20 with ~40k tasks in the db), but at least you figured out how to work around that.

1 Like
4

Thanks a lot, I’ll take a look.
i’m also looking for a DB tuning…maybe it’s related