Bug 784096

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.