Steps to reproduce 1) Import a RHEL manifest 2) Enable RHEL6.2 OS and Optional repos 3) Sync just RHEL6.2 OS repo 4) When complete create changeset, review and promote the entire RHEL product into the next env out of the locker 5) Note the promotion time for this first promotion, for me it was 27 seconds: 2012-01-24T03:08:51-0500: [Worker(delayed_job host:sat-perf-04.idm.lab.bos.redhat.com pid:27728)] Changeset#promote_content completed after 27.0648 6) Create another changeset and repromote the entire RHEL product. Note the time for me was 783 seconds: 2012-01-24T03:22:39-0500: [Worker(delayed_job host:sat-perf-04.idm.lab.bos.redhat.com pid:27728)] Changeset#promote_content completed after 783.1144 Not sure why the 2nd one is so much slower
I took a closer look at your pulp log at the same time (2012-01-24 03:22:39-0500) you saw this timing. If you look at the task that ran during this time frame, it was sync and not clone. And the process that took most time here is createrepo(from 3:11:57 to 3:22:27) (which is about 600 s right there :). Below are the lines from the pulp.log during your promotions. Your first promotion did take about 26 sec as you saw and pulp was invoked with a _clone task. But your second promotion(or whatever call katello made to pulp) invoked a _sync task. The last clone i see that finish was at 2012-01-24 3:08:50. <snip> 2012-01-24 03:08:50,001 27151:140291642210048: pulp.server.tasking.task:INFO: task:440 Task succeeded: Task 97843a14-4662-1 1e1-80ca-e41f137a476c: _clone(ACME_Corporation-Dev-Red_Hat_Enterprise_Linux_Server-Red_Hat_Enterprise_Linux_6_Server_RPMs_x86_64_62, feed=parent, groupid=['product:69', 'env:2', 'org:1', 'content:168'], synchronizer=<pulp.server.api.synchronizers.YumSynchronizer object at 0x7f980ec04d10>, progress_callback=<bound method RepoCloneTask.progress_callback of <pulp.server.api.repo_clone_task.RepoCloneTask object at 0x7f980ec04c10>>, filters=[], id=ACME_Corporation-Red_Hat_Enterprise_Linux_Server-Red_Hat_Enterprise_Linux_6_Server_RPMs_x86_64_62, clone_name=Red Hat Enterprise Linux 6 Server RPMs x86_64 62, relative_path=ACME_Corporation/Dev/content/dist/rhel/server/6/6.2/x86_64/os) </snip> The sync task ran between 2012-01-24 03:09:36,876 to 2012-01-24 03:22:36,605 <snip> from pulp.log 2012-01-24 03:11:57,484 27151:140291642210048: pulp.server.api.synchronizers:INFO: synchronizers:795 Running createrepo, th is may take a few minutes to complete. 2012-01-24 03:11:57,484 27151:140291642210048: pulp.server.util:INFO: util:487 metadata found; taking backup. 2012-01-24 03:11:57,533 27151:140291642210048: pulp.server.util:INFO: util:470 started repo metadata update: ['createrepo', '--database', '--checksum', 'sha256', '-g', '/var/lib/pulp//repos/ACME_Corporation/Dev/content/dist/rhel/server/6/6.2/x86_ 64/os/repodata/a86b4892066cf3909f4d2a565d042501b2940cc3-comps-rhel-x86_64-server-6.xml', '--update', '/var/lib/pulp//repos/ ACME_Corporation/Dev/content/dist/rhel/server/6/6.2/x86_64/os'] 2012-01-24 03:22:27,315 27151:140291642210048: pulp.server.util:INFO: util:520 createrepo on /var/lib/pulp//repos/ACME_Corp oration/Dev/content/dist/rhel/server/6/6.2/x86_64/os finished 2012-01-24 03:22:27,368 27151:140291642210048: pulp.server.util:INFO: util:543 Modifying repo for updateinfo metadata 2012-01-24 03:22:27,791 27151:140291642210048: pulp.server.util:INFO: util:591 modifyrepo with /var/lib/pulp//repos/ACME_Co rporation/Dev/content/dist/rhel/server/6/6.2/x86_64/os/repodata.old/updateinfo.xml on /var/lib/pulp//repos/ACME_Corporation/Dev/content/dist/rhel/server/6/6.2/x86_64/os/repodata finished 2012-01-24 03:22:36,353 27151:140291642210048: pulp.server.util:INFO: util:591 modifyrepo with /var/lib/pulp//repos/ACME_Corporation/Dev/content/dist/rhel/server/6/6.2/x86_64/os//updateinfo.xml on /var/lib/pulp//repos/ACME_Corporation/Dev/content/dist/rhel/server/6/6.2/x86_64/os/repodata finished 2012-01-24 03:22:36,605 27151:140291642210048: pulp.server.api.repo_sync:INFO: repo_sync:314 Adding 0 new errata to repo ACME_Corporation-Dev-Red_Hat_Enterprise_Linux_Server-Red_Hat_Enterprise_Linux_6_Server_RPMs_x86_64_62 2012-01-24 03:22:36,919 27151:140291642210048: pulp.server.tasking.task:INFO: task:440 Task succeeded: Task c1b4f10a-4662-11e1-954a-e41f137a476c: _sync(ACME_Corporation-Dev-Red_Hat_Enterprise_Linux_Server-Red_Hat_Enterprise_Linux_6_Server_RPMs_x86_64_62, synchronizer=<pulp.server.api.synchronizers.YumSynchronizer object at 0x7f97f9614810>, skip={}, max_speed=None, threads=4, progress_callback=<bound method RepoSyncTask.progress_callback of <pulp.server.api.repo_sync_task.RepoSyncTask object at 0x7f97f9d2ee50>>) </snip> So the process that took 783 sec was a sync process which ran createrepo as part of the sync and not clone. I don't know much about katello but looks like you do a clone if the repo is not in the target env and do a sync if its already present. If so what you're seeing make sense. To make sure, I ran a quick script that syncs a RHEL6_2 repo and then clones it (promotion in katello terms) repeatedly. Here's what i see $ ./test_repeated_clones.sh Cloning test_clone_1 Repository [RHEL6_2] is being cloned as [test_clone_1] Clone: Finished Item Details: Tree Files: 6/6 RPMs: 6758/6758 real 0m30.503s user 0m1.531s sys 0m0.119s Cloning test_clone_2 Repository [RHEL6_2] is being cloned as [test_clone_2] Clone: Finished Item Details: Tree Files: 6/6 RPMs: 6758/6758 real 0m30.787s user 0m1.472s sys 0m0.117s Cloning test_clone_3 Repository [RHEL6_2] is being cloned as [test_clone_3] Clone: Finished Item Details: Tree Files: 6/6 RPMs: 6758/6758 real 0m30.609s user 0m1.437s sys 0m0.119s Cloning test_clone_4 Repository [RHEL6_2] is being cloned as [test_clone_4] Clone: Finished Item Details: Tree Files: 6/6 RPMs: 6758/6758 real 0m33.875s user 0m1.602s sys 0m0.119s Cloning test_clone_5 Repository [RHEL6_2] is being cloned as [test_clone_5] Clone: Finished Item Details: Tree Files: 6/6 RPMs: 6758/6758 real 0m31.960s user 0m1.466s sys 0m0.089s deleting test_clone_1 Repository [ test_clone_1 ] being deleted deleting test_clone_2 Repository [ test_clone_2 ] being deleted deleting test_clone_3 Repository [ test_clone_3 ] being deleted deleting test_clone_4 Repository [ test_clone_4 ] being deleted deleting test_clone_5 Repository [ test_clone_5 ] being deleted So based on this, the timing seems to be consistent across 5 consecutive runs. So from pulp's side things seem to doing ok.
Tested on pulp-1.0.0-4.fc15.noarch and I am seeing re-promoting take about 3x as long (43 seconds versus 133 seconds) which is much better than 10x as long. Tested a few times and got a consistent result, so I'm moving to modified.
actually moving to on_q. Note, that any repo with a package filter will not see an improvement.
Today, I tried syncing and resyncing (no filters). Results: 2012-03-05T08:22:33-0500: [Worker(delayed_job host:deploy12.rdu.redhat.com pid:10682)] Changeset#promote_content completed after 269.1442 2012-03-05T09:02:41-0500: [Worker(delayed_job host:deploy12.rdu.redhat.com pid:10682)] Changeset#promote_content completed after 2378.0998
Further tests confirm that this appears to be working. QA Verified.