bzr branch http:// with a pack repository takes too long

Depending on which http implementation you're using, you can:

- activate debug for pycurl in _pycurl.py by uncommenting the line:

        ## curl.setopt(pycurl.VERBOSE, 1)

- activate debug for urllib in _urllib2_wrappers.py by setting DEBUG to 1

DEBUG = 1

I don't think that should generate too much output.

BUT, looking at the numbers of offsets, it's pretty obvious that the server should shoke with a 400: Bad request because the header describing the offsets is just too big.

http readv of 2a0e5ecbd9eea5a28df78a003ced30a4.pack offsets => 33490 collapsed 671
Retry "2a0e5ecbd9eea5a28df78a003ced30a4.pack" with single range request

is a pretty good indication that it occurred.

So this one should hurt.

We already discussed a way to avoid that by issuing several GET requests for a single readv with John, but I didn't implemented it because (from memory) it required to rewrite http/response.py which I didn't want to do at the time.

This has do be done anyway if only to avoid holding the whole file in memory (2 times in some cases), looks like the time has come.

On Sun, 2007-11-25 at 22:04 +0000, vila wrote:
> Depending on which http implementation you're using, you can:
>
> - activate debug for pycurl in _pycurl.py by uncommenting the line:
>
> ## curl.setopt(pycurl.VERBOSE, 1)
>
> - activate debug for urllib in _urllib2_wrappers.py by setting DEBUG to
> 1
>
> DEBUG = 1
>
> I don't think that should generate too much output.

They would be nice as "-Dhttp" at some point.

> BUT, looking at the numbers of offsets, it's pretty obvious that the
> server should shoke with a 400: Bad request because the header
> describing the offsets is just too big.
>
> http readv of 2a0e5ecbd9eea5a28df78a003ced30a4.pack offsets => 33490 collapsed 671
> Retry "2a0e5ecbd9eea5a28df78a003ced30a4.pack" with single range request
>
> is a pretty good indication that it occurred.

Which will go from lowest to highest right?

> So this one should hurt.
>
> We already discussed a way to avoid that by issuing several GET requests
> for a single readv with John, but I didn't implemented it because (from
> memory) it required to rewrite http/response.py which I didn't want to
> do at the time.
>
> This has do be done anyway if only to avoid holding the whole file in
> memory (2 times in some cases), looks like the time has come.

That's my suspicion too. You can probably evaluate this easily yourself
with the bug report - should I try some more, or will you?

-Rob

--
GPG key available at: <http://www.robertcollins.net/keys.txt>.

Some infos :

Regarding:

We do 4 readv's of the pack during fetch:
http readv of 2a0e5ecbd9eea5a28df78a003ced30a4.pack offsets => 14689 collapsed 294
http readv of 2a0e5ecbd9eea5a28df78a003ced30a4.pack offsets => 14689 collapsed 295
http readv of 2a0e5ecbd9eea5a28df78a003ced30a4.pack offsets => 33490 collapsed 671
Retry "2a0e5ecbd9eea5a28df78a003ced30a4.pack" with single range request
http readv of 2a0e5ecbd9eea5a28df78a003ced30a4.pack offsets => 5650 collapsed 114

http already collapsed some offsets, the raw numbers before that are:
'http://bazaar.launchpad.net/%7Elifeless/bzr/repository/.bzr/repository/packs/' replaced by <base> below
Transport.readv(<base>,'2a0e5ecbd9eea5a28df78a003ced30a4.pack',4029)
Transport.readv(<base>,'2a0e5ecbd9eea5a28df78a003ced30a4.pack',15361)
Transport.readv(<base>,'2a0e5ecbd9eea5a28df78a003ced30a4.pack',31598)
Transport.readv(<base>,'2a0e5ecbd9eea5a28df78a003ced30a4.pack',33485)

So your first two readv look strange :
http readv of 2a0e5ecbd9eea5a28df78a003ced30a4.pack offsets => 14689 collapsed 294
http readv of 2a0e5ecbd9eea5a28df78a003ced30a4.pack offsets => 14689 collapsed 295

It's as if they are both related to "my" second readv but 294 != 295 and I can't find an explanation for that difference.

-Dfetch -Dpacks may help a little. The first read is revisions, the second is inventories.
I'm surprised its not collapsing down to 1:).

I believe I know the problem.

pack.make_readv_reader or whatever it is called does the following:
 - take a readv array
 - prepend((0, len(signature))) to it
 - push that down to the transport

So that 'retrying with single range request' means that we're reading from the very beginning, to nearly the very end.

the 4 readvs ends up transferring 5,8M, 25M, 55M and 57M

The third one being the single range request which download far too much (for the reason robert gave above) but worse, the transport then remembers to not issue multiple range requests against that server and issues a subsequent single range request...

The bug is really that the range adapatation policy is fooled by the too many ranges and as said in previous comments the transport should issue several requests instead of a single huge one.

It also shows that we may want to cache the pack files to avoid some downloads but I will not address that for now.

A simpler workaround might be to change the Transport._coalesce_offsets() function to take a "maximum number of ranges" parameter (possibly in the base implementation, or possibly just a class attribute like the others.)

And then it can pass over the collapsed offsets and collapse them further (increasing the fudge factor perhaps) until it can get them down into a smaller set.

See the attached branch for a possible implementation which does just that.

Thanks for pointing me in the right direction.

But, for once, *you* tried too hard ;-) :

 http would request too many ranges (294 > 200),increasing fudge factor from 166782914862269796417081144670355019198970015936234275100365137225948771027692610597171563578031538643191043957534800330675103269083097121420524360998265247159875922818201755803092909167288687752922933023846687910373271576504320960524281740781305426752921714732899756701677789496669028669711669027188902341785855808069930067091482736642846478868032326324098735218574630236658578187070720925632391520545066357127580068110985645199422836821520440636890209174299934909302297076931873482264826230507241634046933889459706843556426495799159190279050847477337512394259749849042640992773520959345798830272396589388897115305400802104397688979304433291198231618940682418274096305125820744721913643883497497877290880515245484938534858543435882665750589951058609515363360903013645450811365401047516850989172490365169902987496671807579360515984604810704476650370319252799739187427386948997621149496381914276204135725947131570881993036698659347503669645725387723759094186148772797119703714600110073291424570301708027715657550388179641700918413127124955527717980661517366677783578348431252644397700343565981509606627152638535494099881293274303300283754630758548408181093461279369728662175452024286828692836764683707033531103781648669689373576516651944345296776810087684354605055 to 333565829724539592834162289340710038397940031872468550200730274451897542055385221194343127156063077286382087915069600661350206538166194242841048721996530494319751845636403511606185818334577375505845866047693375820746543153008641921048563481562610853505843429465799513403355578993338057339423338054377804683571711616139860134182965473285692957736064652648197470437149260473317156374141441851264783041090132714255160136221971290398845673643040881273780418348599869818604594153863746964529652461014483268093867778919413687112852991598318380558101694954675024788519499698085281985547041918691597660544793178777794230610801604208795377958608866582396463237881364836548192610251641489443827287766994995754581761030490969877069717086871765331501179902117219030726721806027290901622730802095033701978344980730339805974993343615158721031969209621408953300740638505599478374854773897995242298992763828552408271451894263141763986073397318695007339291450775447518188372297545594239407429200220146582849140603416055431315100776359283401836826254249911055435961323034733355567156696862505288795400687131963019213254305277070988199762586548606600567509261517096816362186922558739457324350904048573657385673529367414067062207563297339378747153033303888690593553620175368709210111

The bug (which your implementation made obvious) was that http/__init__.py used to declare _max_readv_combined instead of _max_readv_combine (no final 'n'), doh !

Since the huge number of (start, length) was contiguous, the actual code was ok but stop aggregating the offsets above 50 (inherited value for _max_readv_combine).

With that fixed, the number of requested ranges drop to 2.

We now issue four requets of 5.8M , 25M, 24M, 2M.

Looks good to me -- 'bb:approve'

-Rob
--
GPG key available at: <http://www.robertcollins.net/keys.txt>.

This drops the time to get the pack downloaded locally to 9m27. 49 seconds are CPU tome, so thats 8m42. Subtracting 6m5(wget) we get 2m37 to download the indices. The indices are 7m in size. Downloading them individually with wget:
real 0m10.395s
real 0m30.085s
real 0m10.083s
real 0m4.199s

or 55 seconds - so we are wasting 1m42 in round trips and other overhead.
We do 44 round trips, at 333ms each. So thats 14 seconds in round trips.
Which leaves 1m28 unaccounted for.

Is it possible that we are not as efficient as wget at actual data transfer?

Separately I think the next big jump in speed will be denser compression of the content.

Hmm, if each round trip has to do a 3-way hand shake that would add 44 seconds - do we use persistent http connections?

Generally, yes. It would be good to have a way to log if a connection has to be made versus being re-used.

Also, I seem to remember you have to enable persistent connections in Apache.

I know there is:
KeepAlive On
MaxKeepAliveRequests 100
KeepAliveTimeout 15

My "http.conf.rpmnew" has KeepAlive Off. So I think out-of-the-box Apache is configured with keep alive disabled.

Could we check that 'bazaar.launchpad.net' has them enabled? I checked and it seems that people.ubuntu.com has KeepAlive On. So it might just be FC that has KeepAlive disabled by default (my server is several years old at this point).

>>>>> "robert" == Robert Collins <email address hidden> writes:

    robert> This drops the time to get the pack downloaded locally to
    robert> 9m27. 49 seconds are CPU tome, so thats 8m42. Subtracting
    robert> 6m5(wget) we get 2m37 to download the indices. The indices are 7m
    robert> in size. Downloading them individually with wget:
    robert> real 0m10.395s
    robert> real 0m30.085s
    robert> real 0m10.083s
    robert> real 0m4.199s

From here I get:

urllib:
real 91.65
user 11.49
sys 26.99

pycurl:
real 88.68
user 13.30
sys 29.61

Only one http connection issued in both cases (i.e. keep-alive on).

wget:
pack: real 34.71
iix: real 1.04
rix: real 1.05
six: real 0.51
tix: real 2.90

    robert> or 55 seconds

So in my case 40 seconds.

    robert> - so we are wasting 1m42 in round trips and other
    robert> overhead.

50 seconds for me.

    robert> We do 44 round trips, at 333ms each.
    robert> So thats 14 seconds in round trips. Which leaves
    robert> 1m28 unaccounted for.

Where did you get that 44 and that 333 ? We do 62 requests and
transportstats, here, report a 931ms average latency, i.e. the
time between sending the request and receiving a response, which
in my case should account for 57s which is already more than 50s.

Requests issued (initial /%7Elifeless/bzr/repository/.bzr/ cur
for brevity and sorted lexicographically):

GET branch-format
GET branch/branch.conf
GET branch/format

3 times

GET branch/last-revision

2 times

GET branch/tags
GET checkout/format
GET repository/format

3 times

GET repository/indices/2a0e5ecbd9eea5a28df78a003ced30a4.iix

3 times

GET repository/indices/2a0e5ecbd9eea5a28df78a003ced30a4.rix

23 times

GET repository/indices/2a0e5ecbd9eea5a28df78a003ced30a4.six

5 times

GET repository/indices/2a0e5ecbd9eea5a28df78a003ced30a4.tix

13 times

GET repository/pack-names

3 times

GET repository/packs/2a0e5ecbd9eea5a28df78a003ced30a4.pack

4 times

Total 63, transportstats is slightly buggy ;)

So I'd say without further analysis, don't search too hard,
probably your 333 is over optimistic.

But it may be interesting to look at reducing these multiple
readv for .rix and .tix and also getting rid of the multiple GET
for formats.

>>>>> "john" == John A Meinel <email address hidden> writes:

    john> Generally, yes. It would be good to have a way to log
    john> if a connection has to be made versus being re-used.

Not trivial, but I'd look into it, some cases are already logged
(when you get an error the connection is closed so any retry will
make a new one and *that* is logged).

    john> Also, I seem to remember you have to enable persistent
    john> connections in Apache.

    john> I know there is:
    john> KeepAlive On
    john> MaxKeepAliveRequests 100
    john> KeepAliveTimeout 15

    john> My "http.conf.rpmnew" has KeepAlive Off. So I think out-of-the-box
    john> Apache is configured with keep alive disabled.

    john> Could we check that 'bazaar.launchpad.net' has them enabled?

It is and we use it see my other comment.

    john> I checked and it seems that people.ubuntu.com has
    john> KeepAlive On. So it might just be FC that has KeepAlive
    john> disabled by default (my server is several years old at
    john> this point).

Yup, I remember talking about that with you last year, never
encounter another case of KeepAlive off since then.