Push performance

[Greg Ward]

On Wed, Dec 16, 2009 at 1:15 PM, Matt Mackall <mpm at selenic.com> wrote:
>> Is it likely that this slow performance is related to the number of
>> heads?  Or is it something else?  Would profiling be any use, or is it
>> mostly network back-and-forth that's slowing things down?
>
> Come on, Greg, use the debug switch.

<hangs head, red-faced in embarassment>

Sorry... I was naively expecting someone to say, "well, sure, of
course push is O(n) in number of heads, you just need to merge
everything up and it'll fly". ;-)

So I'll do better than --debug: I'll do --debug with a timestamp
attached to each line:

"""
[  0.181224] running ssh testforge "hg -R /src/hg/fullpacs.1214 serve --stdio"
[  0.198224] sending hello command
[  0.198568] sending between command
[  0.390135] remote: 58
[  0.390247] remote: capabilities: unbundle lookup changegroupsubset branchmap
[  0.390338] remote: 1
[  0.485595] pushing to ssh://testforge//src/hg/fullpacs.1214
[  0.590245] remote = <mercurial.sshrepo.sshrepository object at
0x91ccd6c> (url: ssh://testforge//src/hg/fullpacs.1214, match: True)
[  0.590442] bugmap: reading /home/gward/repos/fullpacs.1214/.hg/store/bugmap
[  0.590842] connecting to build on testforge as devel
[  0.699401] sending heads command
[  1.478708] searching for changes
[  1.679633] common changesets up to 88a0258dd3ac 3fbe06f32929
6f8c2aab5fbb 9e01b5fe9eb6 666c18d72277 d84ef7b1437d 10bb3164d98d
0955193174e4 20a96e1448f2 fc3ed5fe369d 33a3e6da2306 2f7058a22cda
4e518ceaa706 d530d050bc3d 58ffdff5f862 0d52bc0caca7 b19a3a7e86d1
ed78d170ee68 dc053b7051a1 567ee7f85e3e 8fe237c92292 213a1a08f2b9
6c5296b34066 d2b90efb5e26 711615c7c95a 45dc4ad05aed d85c3d6b186b
e54d658f82c7 1d411d05bf64 affa8066a019 f12a70b73d1e 1f18ca353a1e
5baef86de723 7d7da1fcec21 751d232fdfa2 3e14f29bff77 281ec8bfefbf
a3e13b14d448 fb7b168e7ef4 035ad44037de e944c163c4de 07644ae90e3c
b18942fce25d 365bf526bd02 f89c9eaf00cd e26e8371b8de 8f095ca83d8e
f5ac45337785 e70272b1d402 a8dc9675a2f8 15deab9d79d6 88ed9f735db5
ac40233af248 7ec9bea87086 917d8627e6a1 b50fef553c0f cb064dbd673a
5cc0986b9ef7 715abcd179ea 7956de6691a3 d146c2751bc0 1d67ca48ce8f
fb1224f4d9f4 d69357098389 dfca8b2f986e 89ac989c99a4 aec920983e0e
e842b3486b5f
[  4.205942] sending branchmap command
[ 12.625008] 1 changesets found
[ 12.625239] list of changesets:
[ 12.625393] 298092cbbea1cf41e206b5d7b29f597b91e1df50
[ 12.625508] sending unbundle command
[ 20.691648] testing remote repo for rev
298092cbbea1cf41e206b5d7b29f597b91e1df50
[ 20.691784] sending lookup command
[ 20.692327] remote repo has 298092cbbea1cf41e206b5d7b29f597b91e1df50
(will update bugs)
[ 20.692534] build at testforge: delete from bugmap where repo_id =
"39465ec3a0b69631033e07e611d10ec14c9f0804" and cset_id =
"298092cbbea1cf41e206b5d7b29f597b91e1df50"
[ 20.693317] build at testforge: insert into bugmap (repo_id, cset_id,
bug, state) values ("39465ec3a0b69631033e07e611d10ec14c9f0804",
"298092cbbea1cf41e206b5d7b29f597b91e1df50", NULL, NULL)
[ 20.693949] commit in <_mysql.connection open to 'testforge' at 93a57cc>
[ 20.881290] remote: adding changesets
[ 20.881520] remote: adding manifests
[ 20.881741] remote: adding file changes
[ 20.881903] remote: added 1 changesets with 1 changes to 1 files
"""

The timestamp is (roughly) seconds from process start.  So the main
culprits are "sending branchmap command" (8.4 sec) and "sending
unbundle command" (8.0 sec).

I do have one extension that runs on the client and updates a
server-side MySQL DB; you can see it taking all of 1 msec to do its
business here.  And there is a server-side pretxnchangegroup hook that
also updates that database; from the logs on the server, that hook
took ~250 msec.

Greg