Problem:
Upgrades to 2.0. The Product page is painfully slow.
Click Content -> Products. The page is “empty” for 28 seconds without any loading indicator. After 28 seconds, the products appear.
Most users would assume there are “no products defined”.
Distribution and version:
CentOS 7 , Foreman 2.0
Can you check your production.log for the same request? It should start with Started GET .... and end with Completed 200 OK
Here are the server logs from the request.
2020-06-09T09:08:22 [I|app|8d722515] Started GET "/notification_recipients" for 10.10.55.93 at 2020-06-09 09:08:22 -0500
2020-06-09T09:08:22 [I|app|8d722515] Processing by NotificationRecipientsController#index as JSON
2020-06-09T09:08:22 [I|app|8d722515] Completed 200 OK in 12ms (Views: 0.2ms | ActiveRecord: 1.5ms)
2020-06-09T09:08:28 [I|app|f721a1ab] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.15.1.1/app/views/dashboard/_sync_widget.html.erb (14485.3ms)
2020-06-09T09:08:28 [I|app|f721a1ab] Completed 200 OK in 14544ms (Views: 1186.0ms | ActiveRecord: 13335.5ms)
2020-06-09T09:08:29 [I|app|cb3444ab] Started GET "/products" for 10.10.55.93 at 2020-06-09 09:08:29 -0500
2020-06-09T09:08:29 [I|app|cb3444ab] Processing by Bastion::BastionController#index as HTML
2020-06-09T09:08:29 [I|app|cb3444ab] Parameters: {"bastion_page"=>"products"}
2020-06-09T09:08:29 [I|app|cb3444ab] Rendering /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.15.1.1/engines/bastion/app/views/bastion/layouts/application.html.erb
2020-06-09T09:08:29 [I|app|cb3444ab] Rendering /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.15.1.1/engines/bastion/app/views/bastion/layouts/assets.html.erb
2020-06-09T09:08:29 [I|app|cb3444ab] Rendering layouts/base.html.erb
2020-06-09T09:08:29 [I|app|cb3444ab] Rendered layouts/base.html.erb (69.0ms)
2020-06-09T09:08:29 [I|app|cb3444ab] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.15.1.1/engines/bastion/app/views/bastion/layouts/assets.html.erb (143.7ms)
2020-06-09T09:08:29 [I|app|cb3444ab] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.15.1.1/engines/bastion/app/views/bastion/layouts/application.html.erb (148.7ms)
2020-06-09T09:08:29 [I|app|cb3444ab] Completed 200 OK in 169ms (Views: 140.1ms | ActiveRecord: 16.1ms)
2020-06-09T09:08:29 [I|app|a1fba056] Started GET "/notification_recipients" for 10.10.55.93 at 2020-06-09 09:08:29 -0500
2020-06-09T09:08:29 [I|app|a1fba056] Processing by NotificationRecipientsController#index as JSON
2020-06-09T09:08:29 [I|app|0fc5d5f2] Started GET "/products/views/products.html" for 10.10.55.93 at 2020-06-09 09:08:29 -0500
2020-06-09T09:08:29 [I|app|9bb804f1] Started GET "/layouts/table-with-header.html" for 10.10.55.93 at 2020-06-09 09:08:29 -0500
2020-06-09T09:08:29 [I|app|a3734b5c] Started GET "/katello/api/v2/products?enabled=true&organization_id=2&page=1&paged=true&per_page=50&search=&sort_by=name&sort_order=ASC" for 10.10.55.93 at 2020-06-09 09:08:29 -0500
2020-06-09T09:08:29 [I|app|a3734b5c] Processing by Katello::Api::V2::ProductsController#index as JSON
2020-06-09T09:08:29 [I|app|a3734b5c] Parameters: {"enabled"=>"true", "organization_id"=>"2", "page"=>"1", "paged"=>"true", "per_page"=>"50", "search"=>"", "sort_by"=>"name", "sort_order"=>"ASC", "api_version"=>"v2"}
2020-06-09T09:08:30 [I|app|e6e51bcd] Started GET "/layouts/partials/page-header-with-actions.html" for 10.10.55.93 at 2020-06-09 09:08:30 -0500
2020-06-09T09:08:30 [I|app|4d29b257] Started GET "/layouts/partials/messages-container.html" for 10.10.55.93 at 2020-06-09 09:08:30 -0500
2020-06-09T09:08:30 [I|app|407c11e5] Started GET "/layouts/partials/table.html" for 10.10.55.93 at 2020-06-09 09:08:30 -0500
2020-06-09T09:08:30 [I|app|a3734b5c] Rendering /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.15.1.1/app/views/katello/api/v2/products/index.json.rabl within katello/api/v2/layouts/collection
2020-06-09T09:08:30 [I|app|c70ab32c] Started GET "/common/views/select-action-dropdown.html" for 10.10.55.93 at 2020-06-09 09:08:30 -0500
2020-06-09T09:08:30 [I|app|a1fba056] Completed 200 OK in 299ms (Views: 0.9ms | ActiveRecord: 10.0ms)
2020-06-09T09:08:30 [I|app|36ec9200] Started GET "/api/v2/bookmarks?search=controller%3Dkatello_products" for 10.10.55.93 at 2020-06-09 09:08:30 -0500
2020-06-09T09:08:30 [I|app|36ec9200] Processing by Api::V2::BookmarksController#index as JSON
2020-06-09T09:08:30 [I|app|36ec9200] Parameters: {"search"=>"controller=katello_products", "apiv"=>"v2"}
2020-06-09T09:08:30 [I|app|36ec9200] Rendering api/v2/bookmarks/index.json.rabl within api/v2/layouts/index_layout
2020-06-09T09:08:30 [I|app|36ec9200] Rendered api/v2/bookmarks/index.json.rabl within api/v2/layouts/index_layout (5.3ms)
2020-06-09T09:08:30 [I|app|36ec9200] Completed 200 OK in 48ms (Views: 14.0ms | ActiveRecord: 6.3ms)
2020-06-09T09:08:39 [I|app|4fb15596] Started GET "/notification_recipients" for 10.10.55.93 at 2020-06-09 09:08:39 -0500
2020-06-09T09:08:39 [I|app|4fb15596] Processing by NotificationRecipientsController#index as JSON
2020-06-09T09:08:40 [I|app|4fb15596] Completed 200 OK in 24ms (Views: 0.3ms | ActiveRecord: 3.3ms)
2020-06-09T09:08:49 [I|app|0b77ac04] Started GET "/notification_recipients" for 10.10.55.93 at 2020-06-09 09:08:49 -0500
2020-06-09T09:08:49 [I|app|0b77ac04] Processing by NotificationRecipientsController#index as JSON
2020-06-09T09:08:49 [I|app|0b77ac04] Completed 200 OK in 13ms (Views: 0.1ms | ActiveRecord: 1.7ms)
2020-06-09T09:08:57 [I|app|a3734b5c] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.15.1.1/app/views/katello/api/v2/products/index.json.rabl within katello/api/v2/layouts/collection (27486.0ms)
2020-06-09T09:08:57 [I|app|a3734b5c] Completed 200 OK in 27544ms (Views: 356.3ms | ActiveRecord: 27155.2ms)
2020-06-09T09:08:59 [I|app|f686e39e] Started GET "/notification_recipients" for 10.10.55.93 at 2020-06-09 09:08:59 -0500
2020-06-09T09:08:59 [I|app|f686e39e] Processing by NotificationRecipientsController#index as JSON
2020-06-09T09:09:00 [I|app|f686e39e] Completed 200 OK in 14ms (Views: 0.2ms | ActiveRecord: 2.4ms)
2020-06-09T09:09:00 [I|app|c6dd40a1] Started GET "/products/views/partials/product-table-sync-status.html" for 10.10.55.93 at 2020-06-09 09:09:00 -0500
2020-06-09T09:09:09 [I|app|4a127805] Started GET "/notification_recipients" for 10.10.55.93 at 2020-06-09 09:09:09 -0500
2020-06-09T09:09:09 [I|app|4a127805] Processing by NotificationRecipientsController#index as JSON
2020-06-09T09:09:09 [I|app|4a127805] Completed 200 OK in 22ms (Views: 0.5ms | ActiveRecord: 3.4ms)You added the log level on wrong level.
If you want to change the default log level, it would be below :logging:
:logging:
:level: debug
:production:
If you want to change it for a specific logger, the indentation is wrong, and it has to be moved one level down.
:loggers:
:sql:
:enabled: true
:level: debug
So it looks for a logger debug and fails!
The foreman wiki was wrong, tbrisker fixed it 
There are some queries in katello 3.15 which seem to be causing the issue.
After some debugging on IRC, at first i though this would be solved by Bug #28818: Product sync-status of latest repo-sync vs. sync-status of all repo-syncs - Katello - Foreman, but it looks like that code is already in Katello 3.15 (despite the redmine claiming it’s fixed in 3.16)?
Most of the slow-down is caused by multiple queries for the tasks, there are multiple queries like:
ForemanTasks::Task::DynflowTask Load (6030.5ms) SELECT DISTINCT foreman_tasks_tasks.*, inner_select.resource_id FROM "foreman_tasks_tasks" INNER JOIN "foreman_tasks_locks" "locks_foreman_tasks_tasks" ON "locks_foreman_tasks_tasks"."task_id" = "foreman_tasks_tasks"."id" INNER JOIN (SELECT MAX(foreman_tasks_tasks.started_at) AS started_at, foreman_tasks_locks.resource_id AS resource_id FROM "foreman_tasks_tasks" INNER JOIN "foreman_tasks_locks" ON "foreman_tasks_locks"."task_id" = "foreman_tasks_tasks"."id" WHERE "foreman_tasks_tasks"."type" IN ('ForemanTasks::Task::DynflowTask') AND "foreman_tasks_tasks"."label" = 'Actions::Katello::Repository::Sync' AND (foreman_tasks_locks.resource_id in (549,550,551,552,553,554,597) and foreman_tasks_locks.resource_type = 'Katello::Repository') GROUP BY foreman_tasks_locks.resource_id) inner_select
This query seems to come from @m-bucher’s attempt to speed things up in https://github.com/Katello/katello/pull/8562 - but it looks like it’s doing two extra joins that cause the resulting query to become painful when there are a lot of tasks in the DB (user has ~15k tasks)
Yes, the current state is that for all products and all their repositories, we need to find the last sync-task and display its status.
Maybe the best solution for that would be to save the last sync-task’s id within the root-repository inside the database.
Is there any need for me to keep my large number of tasks to help solve this one? Thinking of purging the tasks per Feature #8144: Add a purge mechanism for tasks - foreman-tasks - Foreman to help reduce impact.
I believe you can clean up the tasks to speed up your server, you’ve been quite helpful in digging into this!
Before you do, can you run
EXPLAIN ANALYZE SELECT DISTINCT foreman_tasks_tasks.*, inner_select.resource_id FROM "foreman_tasks_tasks" INNER JOIN "foreman_tasks_locks" "locks_foreman_tasks_tasks" ON "locks_foreman_tasks_tasks"."task_id" = "foreman_tasks_tasks"."id" INNER JOIN (SELECT MAX(foreman_tasks_tasks.started_at) AS started_at, foreman_tasks_locks.resource_id AS resource_id FROM "foreman_tasks_tasks" INNER JOIN "foreman_tasks_locks" ON "foreman_tasks_locks"."task_id" = "foreman_tasks_tasks"."id" WHERE "foreman_tasks_tasks"."type" IN ('ForemanTasks::Task::DynflowTask') AND "foreman_tasks_tasks"."label" = 'Actions::Katello::Repository::Sync' AND (foreman_tasks_locks.resource_id in (549,550,551,552,553,554,597) and foreman_tasks_locks.resource_type = 'Katello::Repository') GROUP BY foreman_tasks_locks.resource_id) inner_select
on your pgsql server just so we get a full understanding of why this query is so slow?
That query isn’t working. (login as postgres, \c foreman)
ERROR: syntax error at or near “;”
LINE 2: ;
EDIT: Ah… your original posting of the SQL missed a bit… trying now.
# EXPLAIN ANALYZE SELECT DISTINCT foreman_tasks_tasks.*, inner_select.resource_id FROM "foreman_tasks_tasks" INNER JOIN "foreman_tasks_locks" "locks_foreman_tasks_tasks" ON "locks_foreman_tasks_tasks"."task_id" = "foreman_tasks_tasks"."id" INNER JOIN (SELECT MAX(foreman_tasks_tasks.started_at) AS started_at, foreman_tasks_locks.resource_id AS resource_id FROM "foreman_tasks_tasks" INNER JOIN "foreman_tasks_locks" ON "foreman_tasks_locks"."task_id" = "foreman_tasks_tasks"."id" WHERE "foreman_tasks_tasks"."type" IN ('ForemanTasks::Task::DynflowTask') AND "foreman_tasks_tasks"."label" = 'Actions::Katello::Repository::Sync' AND (foreman_tasks_locks.resource_id in (549,550,551,552,553,554,597) and foreman_tasks_locks.resource_type = 'Katello::Repository') GROUP BY foreman_tasks_locks.resource_id) inner_select
ON inner_select.started_at = foreman_tasks_tasks.started_at
AND inner_select.resource_id = locks_foreman_tasks_tasks.resource_id WHERE "foreman_tasks_tasks"."type" IN ('ForemanTasks::Task::DynflowTask');
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
------------------
Unique (cost=2666.99..2667.06 rows=2 width=245) (actual time=36.491..36.519 rows=7 loops=1)
-> Sort (cost=2666.99..2666.99 rows=2 width=245) (actual time=36.488..36.490 rows=14 loops=1)
Sort Key: foreman_tasks_tasks.id, foreman_tasks_tasks.label, foreman_tasks_tasks.started_at, foreman_tasks_tasks.ended_at, foreman_tasks_tasks.state, foreman_tasks_tasks.result, foreman_tasks_tasks.exte
rnal_id, foreman_tasks_tasks.parent_task_id, foreman_tasks_tasks.start_at, foreman_tasks_tasks.start_before, foreman_tasks_tasks.action, foreman_tasks_tasks.state_updated_at, foreman_tasks_tasks.user_id, inner_s
elect.resource_id
Sort Method: quicksort Memory: 32kB
-> Nested Loop (cost=1659.62..2666.98 rows=2 width=245) (actual time=34.436..36.354 rows=14 loops=1)
Join Filter: (inner_select.resource_id = locks_foreman_tasks_tasks.resource_id)
Rows Removed by Join Filter: 21
-> Hash Join (cost=1659.33..2574.79 rows=163 width=245) (actual time=34.398..36.202 rows=7 loops=1)
Hash Cond: (foreman_tasks_tasks.started_at = inner_select.started_at)
-> Seq Scan on foreman_tasks_tasks (cost=0.00..852.71 rows=16297 width=241) (actual time=0.026..12.967 rows=16307 loops=1)
Filter: ((type)::text = 'ForemanTasks::Task::DynflowTask'::text)
-> Hash (cost=1657.40..1657.40 rows=155 width=12) (actual time=20.136..20.136 rows=7 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 9kB
-> Subquery Scan on inner_select (cost=1652.00..1657.40 rows=155 width=12) (actual time=19.009..20.127 rows=7 loops=1)
-> GroupAggregate (cost=1652.00..1655.85 rows=155 width=12) (actual time=19.007..20.122 rows=7 loops=1)
Group Key: foreman_tasks_locks.resource_id
-> Sort (cost=1652.00..1652.77 rows=306 width=12) (actual time=18.818..19.190 rows=2814 loops=1)
Sort Key: foreman_tasks_locks.resource_id
Sort Method: quicksort Memory: 228kB
-> Hash Join (cost=1035.34..1639.37 rows=306 width=12) (actual time=13.315..17.446 rows=2814 loops=1)
Hash Cond: (foreman_tasks_locks.task_id = foreman_tasks_tasks_1.id)
-> Bitmap Heap Scan on foreman_tasks_locks (cost=67.51..665.33 rows=839 width=20) (actual time=0.981..3.034 rows=2814 loops=1)
Recheck Cond: (((resource_type)::text = 'Katello::Repository'::text) AND (resource_id = ANY ('{549,550,551,552,553,554,597}'::integer[])))
Heap Blocks: exact=417
-> Bitmap Index Scan on index_foreman_tasks_locks_on_resource_type_and_resource_id (cost=0.00..67.31 rows=839 width=0) (actual time=0.877..0.877 rows=28
14 loops=1)
Index Cond: (((resource_type)::text = 'Katello::Repository'::text) AND (resource_id = ANY ('{549,550,551,552,553,554,597}'::integer[])))
-> Hash (cost=893.45..893.45 rows=5950 width=24) (actual time=12.222..12.222 rows=5950 loops=1)
Buckets: 8192 Batches: 1 Memory Usage: 390kB
-> Seq Scan on foreman_tasks_tasks foreman_tasks_tasks_1 (cost=0.00..893.45 rows=5950 width=24) (actual time=0.016..9.303 rows=5950 loops=1)
Filter: (((type)::text = 'ForemanTasks::Task::DynflowTask'::text) AND ((label)::text = 'Actions::Katello::Repository::Sync'::text))
Rows Removed by Filter: 10357
-> Index Scan using index_foreman_tasks_locks_on_task_id on foreman_tasks_locks locks_foreman_tasks_tasks (cost=0.29..0.53 rows=3 width=20) (actual time=0.015..0.017 rows=5 loops=7)
Index Cond: (task_id = foreman_tasks_tasks.id)
Planning Time: 2.387 ms
Execution Time: 36.754 ms
(35 rows)
Annoyingly, this query runs quickly when executed in postgresql directly only producing 5-6 rows. I haven’t cleared my tasks yet, and still have ~15k.
The products page still loads slowly at 30 seconds
that is quite odd indeed… could it be there is something locking one of these tables when loading the products page leading to the slow queries we saw in your logs?
I just ran the explain again while the products page was loading… now the products page loads within a reasonable second or two 
No idea. If this happens again i’ll grab the explain to find out why. Maybe an automated task ran and “fixed” whatever was blocking the queries?
Could it be that the table had a lot of records that were deleted in the past and your explain query forced a recalculation of the statistics or vacuum run?
Hello
i am having the exact same problem. Products page after the upgrade is unbearable ~40s to load it.
2020-06-11T09:36:36 [I|app|ab7d551e] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.15.1.1/app/views/katello/api/v2/products/index.json.rabl within katello/api/v2/layouts/collection (41740.3ms)
2020-06-11T09:36:36 [I|app|ab7d551e] Completed 200 OK in 41822ms (Views: 713.8ms | ActiveRecord: 41046.1ms)
I also run the query you provided with “EXPLAIN ANALYZE” and it run within:
Planning Time: 2.157 ms
Execution Time: 7143.341 ms
I saw that you suggested to remove old tasks which would maybe help with the performance. I should have total of ~63k tasks but when i try to perform the cleanup i am getting an error from:
[root@ foreman]# foreman-rake foreman_tasks:cleanup TASK_SEARCH=‘label ~ *’ AFTER=‘1d’ VERBOSE=true
rake aborted!
The Dynflow world was not initialized yet. If your plugin uses it, make sure to call Rails.application.dynflow.require! in some initializer
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.3/lib/dynflow/rails.rb:75:inworld' /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-1.1.1/lib/foreman_tasks/cleaner.rb:80:ininitialize’
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-1.1.1/lib/foreman_tasks/cleaner.rb:8:innew' /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-1.1.1/lib/foreman_tasks/cleaner.rb:8:inrun’
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-1.1.1/lib/foreman_tasks/tasks/cleanup.rake:37:inblock (3 levels) in <top (required)>' /opt/rh/rh-ruby25/root/usr/share/gems/gems/rake-12.3.0/exe/rake:27:in<top (required)>’
Tasks: TOP => foreman_tasks:cleanup => foreman_tasks:cleanup:run
(See full trace by running task with --trace)
Note that i upgraded from:
Foreman 1.24.3 -> 2.0.1
Katello 3.14.1 -> 3.15.1.1
Turned also on debugging and top SQL consumers by time are these:
2020-06-11T10:08:04 [D|sql|4b64480e] ForemanTasks::Task::DynflowTask Load (6890.4ms) SELECT DISTINCT foreman_tasks_tasks., inner_select.resource_id FROM “foreman_tasks_tasks” INNER JOIN “foreman_tasks_locks” “locks_foreman_tasks_tasks” ON “locks_foreman_tasks_tasks”.“task_id” = “foreman_tasks_tasks”.“id” INNER JOIN (SELECT MAX(foreman_tasks_tasks.started_at) AS started_at, foreman_tasks_locks.resource_id AS resource_id FROM “foreman_tasks_tasks” INNER JOIN “foreman_tasks_locks” ON “foreman_tasks_locks”.“task_id” = “foreman_tasks_tasks”.“id” WHERE “foreman_tasks_tasks”.“type” IN (‘ForemanTasks::Task::DynflowTask’) AND “foreman_tasks_tasks”.“label” = ‘Actions::Katello::Repository::Sync’ AND (foreman_tasks_locks.resource_id in (59,516,517,518,520,519,8203,8241) and foreman_tasks_locks.resource_type = ‘Katello::Repository’) GROUP BY foreman_tasks_locks.resource_id) inner_select
2020-06-11T10:08:11 [D|sql|4b64480e] ForemanTasks::Task::DynflowTask Load (7093.2ms) SELECT foreman_tasks_tasks. FROM “foreman_tasks_tasks” INNER JOIN “foreman_tasks_locks” ON “foreman_tasks_locks”.“task_id” = “foreman_tasks_tasks”.“id” WHERE “foreman_tasks_tasks”.“type” IN (‘ForemanTasks::Task::DynflowTask’) AND “foreman_tasks_tasks”.“label” = $1 AND (foreman_tasks_locks.resource_id in (59,516,517,518,520,519,8203,8241) and foreman_tasks_locks.resource_type = ‘Katello::Repository’) ORDER BY started_at desc LIMIT $2 [[“label”, “Actions::Katello::Repository::Sync”], [“LIMIT”, 1]]
2020-06-11T10:08:18 [D|sql|4b64480e] ForemanTasks::Task::DynflowTask Load (6703.9ms) SELECT DISTINCT foreman_tasks_tasks., inner_select.resource_id FROM “foreman_tasks_tasks” INNER JOIN “foreman_tasks_locks” “locks_foreman_tasks_tasks” ON “locks_foreman_tasks_tasks”.“task_id” = “foreman_tasks_tasks”.“id” INNER JOIN (SELECT MAX(foreman_tasks_tasks.started_at) AS started_at, foreman_tasks_locks.resource_id AS resource_id FROM “foreman_tasks_tasks” INNER JOIN “foreman_tasks_locks” ON “foreman_tasks_locks”.“task_id” = “foreman_tasks_tasks”.“id” WHERE “foreman_tasks_tasks”.“type” IN (‘ForemanTasks::Task::DynflowTask’) AND “foreman_tasks_tasks”.“label” = ‘Actions::Katello::Repository::Sync’ AND (foreman_tasks_locks.resource_id in (57,10,9,60,1361,8,7,6590,8202,8240) and foreman_tasks_locks.resource_type = ‘Katello::Repository’) GROUP BY foreman_tasks_locks.resource_id) inner_select
2020-06-11T10:08:24 [D|sql|4b64480e] ForemanTasks::Task::DynflowTask Load (6666.9ms) SELECT foreman_tasks_tasks. FROM “foreman_tasks_tasks” INNER JOIN “foreman_tasks_locks” ON “foreman_tasks_locks”.“task_id” = “foreman_tasks_tasks”.“id” WHERE “foreman_tasks_tasks”.“type” IN (‘ForemanTasks::Task::DynflowTask’) AND “foreman_tasks_tasks”.“label” = $1 AND (foreman_tasks_locks.resource_id in (57,10,9,60,1361,8,7,6590,8202,8240) and foreman_tasks_locks.resource_type = ‘Katello::Repository’) ORDER BY started_at desc LIMIT $2 [[“label”, “Actions::Katello::Repository::Sync”], [“LIMIT”, 1]]
2020-06-11T10:08:31 [D|sql|4b64480e] ForemanTasks::Task::DynflowTask Load (6877.8ms) SELECT DISTINCT foreman_tasks_tasks., inner_select.resource_id FROM “foreman_tasks_tasks” INNER JOIN “foreman_tasks_locks” “locks_foreman_tasks_tasks” ON “locks_foreman_tasks_tasks”.“task_id” = “foreman_tasks_tasks”.“id” INNER JOIN (SELECT MAX(foreman_tasks_tasks.started_at) AS started_at, foreman_tasks_locks.resource_id AS resource_id FROM “foreman_tasks_tasks” INNER JOIN “foreman_tasks_locks” ON “foreman_tasks_locks”.“task_id” = “foreman_tasks_tasks”.“id” WHERE “foreman_tasks_tasks”.“type” IN (‘ForemanTasks::Task::DynflowTask’) AND “foreman_tasks_tasks”.“label” = ‘Actions::Katello::Repository::Sync’ AND (foreman_tasks_locks.resource_id in (10309,10310,10311,10312,10313,10314,10315,10316,10349) and foreman_tasks_locks.resource_type = ‘Katello::Repository’) GROUP BY foreman_tasks_locks.resource_id) inner_select
2020-06-11T10:08:38 [D|sql|4b64480e] ForemanTasks::Task::DynflowTask Load (6558.7ms) SELECT foreman_tasks_tasks. FROM “foreman_tasks_tasks” INNER JOIN “foreman_tasks_locks” ON “foreman_tasks_locks”.“task_id” = “foreman_tasks_tasks”.“id” WHERE “foreman_tasks_tasks”.“type” IN (‘ForemanTasks::Task::DynflowTask’) AND “foreman_tasks_tasks”.“label” = $1 AND (foreman_tasks_locks.resource_id in (10309,10310,10311,10312,10313,10314,10315,10316,10349) and foreman_tasks_locks.resource_type = ‘Katello::Repository’) ORDER BY started_at desc LIMIT $2 [[“label”, “Actions::Katello::Repository::Sync”], [“LIMIT”, 1]]
End result:
2020-06-11T10:08:38 [I|app|4b64480e] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.15.1.1/app/views/katello/api/v2/products/index.json.rabl within katello/api/v2/layouts/collection (41003.5ms)
Can you please share the full output of the EXPLAIN ANALYZE for one of those slow queries? Also, can you check if running VACUUM FULL on your db improves the speed?
Running full vacuum was one of the first thing i did and it did not help anything.
su - postgres -c ‘vacuumdb --full --dbname=foreman’
Full output of EXPLAIN ANALYZE:
foreman=> EXPLAIN ANALYZE SELECT DISTINCT foreman_tasks_tasks.*, inner_select.resource_id FROM “foreman_tasks_tasks” INNER JOIN “foreman_tasks_locks” “locks_foreman_tasks_tasks” ON “locks_foreman_tasks_tasks”.“task_id” = “foreman_tasks_tasks”.“id” INNER JOIN (SELECT MAX(foreman_tasks_tasks.started_at) AS started_at, foreman_tasks_locks.resource_id AS resource_id FROM “foreman_tasks_tasks” INNER JOIN “foreman_tasks_locks” ON “foreman_tasks_locks”.“task_id” = “foreman_tasks_tasks”.“id” WHERE “foreman_tasks_tasks”.“type” IN (‘ForemanTasks::Task::DynflowTask’) AND “foreman_tasks_tasks”.“label” = ‘Actions::Katello::Repository::Sync’ AND (foreman_tasks_locks.resource_id in (59,516,517,518,520,519,8203,8241) and foreman_tasks_locks.resource_type = ‘Katello::Repository’) GROUP BY foreman_tasks_locks.resource_id) inner_select
foreman-> ON inner_select.started_at = foreman_tasks_tasks.started_at
foreman-> AND inner_select.resource_id = locks_foreman_tasks_tasks.resource_id WHERE “foreman_tasks_tasks”.“type” IN (‘ForemanTasks::Task::DynflowTask’);
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------
Unique (cost=203.36..203.51 rows=4 width=272) (actual time=6960.560..6960.573 rows=8 loops=1)
-> Sort (cost=203.36..203.37 rows=4 width=272) (actual time=6960.559..6960.560 rows=16 loops=1)
Sort Key: foreman_tasks_tasks.id, foreman_tasks_tasks.label, foreman_tasks_tasks.started_at, foreman_tasks_tasks.ended_at, foreman_tasks_tasks.state, foreman_tasks_tasks.result, foreman_tasks_tasks.external_id, foreman_tasks_tasks.parent_task_id, foreman_tasks_tasks.start_at, foreman_tasks_tasks.start_befor
e, foreman_tasks_tasks.action, foreman_tasks_tasks.state_updated_at, foreman_tasks_tasks.user_id, foreman_tasks_locks.resource_id
Sort Method: quicksort Memory: 33kB
-> Nested Loop (cost=120.65..203.32 rows=4 width=272) (actual time=6934.744..6960.504 rows=16 loops=1)
Join Filter: (foreman_tasks_locks.resource_id = locks_foreman_tasks_tasks.resource_id)
Rows Removed by Join Filter: 24
-> Nested Loop (cost=120.23..128.12 rows=2 width=272) (actual time=6934.731..6960.419 rows=8 loops=1)
-> GroupAggregate (cost=102.47..102.49 rows=1 width=12) (actual time=6930.797..6931.327 rows=8 loops=1)
Group Key: foreman_tasks_locks.resource_id
-> Sort (cost=102.47..102.48 rows=1 width=12) (actual time=6930.708..6930.975 rows=3170 loops=1)
Sort Key: foreman_tasks_locks.resource_id
Sort Method: quicksort Memory: 245kB
-> Nested Loop (cost=37.90..102.46 rows=1 width=12) (actual time=14.587..6929.493 rows=3170 loops=1)
-> Bitmap Heap Scan on foreman_tasks_tasks foreman_tasks_tasks_1 (cost=4.44..12.28 rows=2 width=24) (actual time=0.848..5.291 rows=5614 loops=1)
Recheck Cond: (((type)::text = 'ForemanTasks::Task::DynflowTask'::text) AND ((label)::text = 'Actions::Katello::Repository::Sync'::text))
Heap Blocks: exact=1088
-> Bitmap Index Scan on index_foreman_tasks_tasks_on_type_and_label (cost=0.00..4.43 rows=2 width=0) (actual time=0.723..0.724 rows=5614 loops=1)
Index Cond: (((type)::text = 'ForemanTasks::Task::DynflowTask'::text) AND ((label)::text = 'Actions::Katello::Repository::Sync'::text))
-> Bitmap Heap Scan on foreman_tasks_locks (cost=33.46..45.08 rows=1 width=20) (actual time=1.231..1.231 rows=1 loops=5614)
Recheck Cond: ((task_id = foreman_tasks_tasks_1.id) AND ((resource_type)::text = 'Katello::Repository'::text))
Filter: (resource_id = ANY ('{59,516,517,518,520,519,8203,8241}'::integer[]))
Rows Removed by Filter: 1
Heap Blocks: exact=5623
-> BitmapAnd (cost=33.46..33.46 rows=3 width=0) (actual time=1.229..1.229 rows=0 loops=5614)
-> Bitmap Index Scan on index_foreman_tasks_locks_on_task_id (cost=0.00..16.60 rows=558 width=0) (actual time=0.004..0.004 rows=5 loops=5614)
Index Cond: (task_id = foreman_tasks_tasks_1.id)
-> Bitmap Index Scan on index_foreman_tasks_locks_on_resource_type_and_resource_id (cost=0.00..16.60 rows=558 width=0) (actual time=1.236..1.236 rows=21466 loops=5558)
Index Cond: ((resource_type)::text = 'Katello::Repository'::text)
-> Bitmap Heap Scan on foreman_tasks_tasks (cost=17.76..25.60 rows=2 width=268) (actual time=3.633..3.633 rows=1 loops=8)
Recheck Cond: ((started_at = (max(foreman_tasks_tasks_1.started_at))) AND ((type)::text = 'ForemanTasks::Task::DynflowTask'::text))
Heap Blocks: exact=8
-> BitmapAnd (cost=17.76..17.76 rows=2 width=0) (actual time=3.627..3.627 rows=0 loops=8)
-> Bitmap Index Scan on index_foreman_tasks_tasks_on_started_at (cost=0.00..6.65 rows=315 width=0) (actual time=0.003..0.003 rows=1 loops=8)
Index Cond: (started_at = (max(foreman_tasks_tasks_1.started_at)))
-> Bitmap Index Scan on index_foreman_tasks_tasks_on_type (cost=0.00..10.78 rows=315 width=0) (actual time=3.600..3.600 rows=63028 loops=8)
Index Cond: ((type)::text = 'ForemanTasks::Task::DynflowTask'::text)
-> Index Scan using index_foreman_tasks_locks_on_task_id on foreman_tasks_locks locks_foreman_tasks_tasks (cost=0.42..30.63 rows=558 width=20) (actual time=0.006..0.007 rows=5 loops=8)
Index Cond: (task_id = foreman_tasks_tasks.id)
Planning Time: 0.699 ms
Execution Time: 6960.680 ms
(41 rows)