Today, the sync from the main to the content proxy is slow again. I have checked and every sync has the problem. I publish and promote the content views each workday. Each time it syncs a new version of EPEL9. Each time it takes very long. Each time it’s only EPEL 9. All other repos in the same sync only need a few seconds.
On Monday last week and today it takes more then 4 hours. Tuesday through Friday morning it was approx. 2 hours each. So it seems to be related to the amount of changes in the repository.
It must be related to whatever is happening during “Associating Content” as that’s the part where it’s working on right now for a long time:
{"smart_proxy_history_id"=>27041,
"pulp_tasks"=>
[{"pulp_href"=>"/pulp/api/v3/tasks/cbe66dc4-7e37-4a22-ba7f-53d6eaae62cc/",
"pulp_created"=>"2023-09-25T02:35:04.787+00:00",
"state"=>"running",
"name"=>"pulp_rpm.app.tasks.synchronizing.synchronize",
"logging_cid"=>"cfa4d081-1054-4eec-8da3-098a543191df",
"started_at"=>"2023-09-25T02:35:04.895+00:00",
"worker"=>"/pulp/api/v3/workers/cb65b093-abb8-40a7-b0ff-1fd7217f92ea/",
"child_tasks"=>[],
"progress_reports"=>
[{"message"=>"Downloading Metadata Files",
"code"=>"sync.downloading.metadata",
"state"=>"completed",
"done"=>6},
{"message"=>"Downloading Artifacts",
"code"=>"sync.downloading.artifacts",
"state"=>"completed",
"done"=>0},
{"message"=>"Associating Content",
"code"=>"associating.content",
"state"=>"running",
"done"=>182},
{"message"=>"Skipping Packages",
"code"=>"sync.skipped.packages",
"state"=>"completed",
"total"=>0,
"done"=>0},
{"message"=>"Parsed Packages",
"code"=>"sync.parsing.packages",
"state"=>"completed",
"total"=>37449,
"done"=>37449},
{"message"=>"Parsed Advisories",
"code"=>"sync.parsing.advisories",
"state"=>"completed",
"total"=>6417,
"done"=>6417},
{"message"=>"Parsed Comps",
"code"=>"sync.parsing.comps",
"state"=>"completed",
"total"=>22,
"done"=>22}],
"created_resources"=>[""],
"reserved_resources_record"=>
["/pulp/api/v3/repositories/rpm/rpm/43e7b651-8399-4bda-b54e-900dea17af7e/",
"shared:/pulp/api/v3/remotes/rpm/rpm/6732d168-717d-47d1-9406-5fbb1fb52efd/"]}],
"task_groups"=>[],
"poll_attempts"=>{"total"=>854, "failed"=>0}}
Some stats: day/duration/associating content/parsed packages/un-associating content
Mon/14177s/259/37177/14
Tue/8080s/59/37217/8
Wed/5258s/34/37234/11
Thu/6582s/28/37249/6
Fri/6954s/79/37311/7
currently running: Mon/13608s+/182+/37449/pending
One more sample of currently running query:
active | 2023-09-25 08:17:35.036825+02 | 2023-09-25 08:23:12.863966+02 | SELECT "core_content"."pulp_id" FROM "core_content" WHERE ("core_content"."pulp_id" IN ('a6be1308-1695-4f5f-8d39-e05934b2793b'::uuid, 'fc243bc6-7b02-45a5-9709-8abbfb8c8bc8'::uuid, '469827ab-902e-42b7-a0e8-80232ed12415'::uuid, 'e3873203-8bea-477f-9309-a2fe62ad3df7':
:uuid) AND NOT ("core_content"."pulp_id" IN (SELECT V0."pulp_id" FROM "core_content" V0 WHERE V0."pulp_id" IN (SELECT U0."content_id" FROM "core_repositorycontent" U0 INNER JOIN "core_repositoryversion" U2 ON (U0."version_added_id" = U2."pulp_id") LEFT OUTER JOIN "core_repositoryversion" U3 ON (U0."version_removed_id" = U3."pulp_id") WHE
RE (U0."repository_id" = '43e7b651-8399-4bda-b54e-900dea17af7e'::uuid AND U2."number" <= 239 AND NOT (U3."number" <= 239 AND U3."number" IS NOT NULL))))))
pulpcore=# explain SELECT "core_content"."pulp_id" FROM "core_content" WHERE ("core_content"."pulp_id" IN ('a6be1308-1695-4f5f-8d39-e05934b2793b'::uuid, 'fc243bc6-7b02-45a5-9709-8abbfb8c8bc8'::uuid, '469827ab-902e-42b7-a0e8-80232ed12415'::uuid, 'e3873203-8bea-477f-9309-a2fe62ad3df7'::uuid) AND NOT ("core_content"."pulp_id" IN (SELECT V0."pulp_id" FROM "core_content" V0 WHERE V0."pulp_id" IN (SELECT U0."content_id" FROM "core_repositorycontent" U0 INNER JOIN "core_repositoryversion" U2 ON (U0."version_added_id" = U2."pulp_id") LEFT OUTER JOIN "core_repositoryversion" U3 ON (U0."version_removed_id" = U3."pulp_id") WHERE (U0."repository_id" = '43e7b651-8399-4bda-b54e-900dea17af7e'::uuid AND U2."number" <= 239 AND NOT (U3."number" <= 239 AND U3."number" IS NOT NULL))))));
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Index Only Scan using core_content_pkey on core_content (cost=49053.38..49082.73 rows=2 width=16)
Index Cond: (pulp_id = ANY ('{a6be1308-1695-4f5f-8d39-e05934b2793b,fc243bc6-7b02-45a5-9709-8abbfb8c8bc8,469827ab-902e-42b7-a0e8-80232ed12415,e3873203-8bea-477f-9309-a2fe62ad3df7}'::uuid[]))
Filter: (NOT (hashed SubPlan 1))
SubPlan 1
-> Nested Loop Semi Join (cost=4300.33..49052.96 rows=1 width=16)
Join Filter: (v0.pulp_id = u0.content_id)
-> Seq Scan on core_content v0 (cost=0.00..7184.58 rows=280358 width=16)
-> Materialize (cost=4300.33..37663.01 rows=1 width=16)
-> Nested Loop (cost=4300.33..37663.00 rows=1 width=16)
Join Filter: (u0.version_added_id = u2.pulp_id)
-> Hash Left Join (cost=4300.33..37592.75 rows=1 width=32)
Hash Cond: (u0.version_removed_id = u3.pulp_id)
Filter: ((u3.number > 239) OR (u3.number IS NULL))
-> Bitmap Heap Scan on core_repositorycontent u0 (cost=4234.60..37403.04 rows=47232 width=48)
Recheck Cond: (repository_id = '43e7b651-8399-4bda-b54e-900dea17af7e'::uuid)
-> Bitmap Index Scan on core_repositorycontent_repository_id_1946e61b (cost=0.00..4222.79 rows=47232 width=0)
Index Cond: (repository_id = '43e7b651-8399-4bda-b54e-900dea17af7e'::uuid)
-> Hash (cost=43.10..43.10 rows=1810 width=20)
-> Seq Scan on core_repositoryversion u3 (cost=0.00..43.10 rows=1810 width=20)
-> Seq Scan on core_repositoryversion u2 (cost=0.00..47.62 rows=1810 width=16)
Filter: (number <= 239)
(21 rows)
Just wondering: slow queries are often due to missing indices. Could it be a database migration got wrong and didn’t create a index or maybe it was forgotten? How I can check if I have all indices I should have in the content proxy database?