Status of speed regressions...

Sat Nov 20 10:16:55 CST 2010

On Nov 19, 2010, at 11:03 PM, Matt Mackall wrote:

> On Fri, 2010-11-19 at 18:40 +0100, Jason Harris wrote:
>> Hi All,
>> 
>> I was just wondering what the status of fixing the speed regressions is? Are there patches I can apply?
> 
>> I have a MacHg with Mercurial 1.5.4 (baseline) with 1.6.4 (10-15%
>> slower) and with 1.7.1 (20% slower). I can publish timings but I think
>> others have noticed this as well...
> 
> Seems a refresher is in order.
> 
> Here is what I expect of someone who is basing an ostensibly serious
> product on our software:
> 
> - proactively test BEFORE every release
> - report issues IMMEDIATELY
> - and with SPECIFICS
> - work to fix issues UPSTREAM, don't patch our code in your releases

<sigh> do we really have to go here... yet again???

Why are your emails so often abrasive? I wish you would communicate in a more
friendly and professional manner.

I need to remind you that I do MacHg for the community for free in my spare
time. My real job required all my real attention and actually all of my spare
time as well during the last number of months. Thus I realistically couldn't
follow many of the details of the Mercurial scene during the last 4 months. For
now my spare time is my own again.  In my real job we go through periods where I
am in very high demand, and I have basically no real free time to myself. This
will happen repeatedly in the future.

I don't work for you or the mercurial project. Although, I of course try to help
out and do what I can when I can. Thus, despite your expectations, your stated
desires above, although good in a perfect world, are unlikely to often be
fulfilled in practice.

As I have stated at length I use Mercurial as a tool.  Like you use Python, etc.
 Just like you guys are using python 2.6 not 2.7 and certainly not 3.1.2. 
Understandably, your priorities are to provide a good revision control system,
not hack away on python.  Understandably, my priority is to provide a good
FrontEnd for Mercurial.

As for patching issues upstream, we have already been over all of that. MacHg
currently only differs in this patch provided by Martin Geisler
http://bitbucket.org/jfh/machg/changeset/23cef03f3f85 which is applied on top of
Mercurial.  (See the details in this mailing lists archives.) I would of course
prefer to use a pristine Mercurial client, but unless you have some new work
around other than the other impractical ones you have come up with in the past,
this patch will remain. In a more general theme... if I can solve issues by
changing core Mercurial and it is hundreds of times easier to do this then
working around this in cocoa, I will in the future again proceed to modify
Mercurial to suit the needs of MacHg (I will of course tell the community about
it). This is in keeping with the traditions of open source software.

Anyway I am refreshing a few of the issues that have built up during the last
couple of months. (While I have time...) And following this I will try to extend
things, eg I would like to have a nice interface to patch queues, split
changesets, a nice annotation explore view, etc. And many other additions.

In fact if I had lots of time to spend on things I would dig into Mercurial
coding and try and add support for eg multiple Undo, blacklisting of stripped
changesets, delta-diffs (the diffing of diffs without line numbers so you can
see if the same patch is applied in different places in the tree...) and other
things which I think would be very desirable. But I regrettably don't have that
time.

Consequently, I just try and make a good FrontEnd for the Macintosh.
</sigh>

> In other words, what I wanted to see is an email a month ago during our
> code freeze that said "Hi, doing my routine pre-release test for 1.7 and
> I see that performance for <foo> has regressed 20%, here's how I
> reproduce it without MacHG". Then you're much more likely to get a
> response like "Good spotting, thanks, please test this fix for 1.7."
> 
> That's the right way. Your email is the opposite of that.

What I wanted to see from you would have been: "Ohh... We are not aware of any
speed regressions. Could you please send us details as soon as possible. As
always, if its possible for you we would like you to do pre-release testing.
Links and instructions are here XYZ. Cheers, Matt..."

Now *that* would have been professional, friendly and much more likely to elicit
a positive response from me.

> Now please give us some specifics.

Well you yourself noticed there was a startup time regression.

http://www.selenic.com/pipermail/mercurial-devel/2010-November/025903.html

Thus what transpired is that I thought this was a know issue and so I did some
quick tests to see if I could reproduce these (which it seemed I could), and
then emailed basically asking what is the status of these issues. (Spending an
hour going through and testing things which you all knew about would obviously
be a waste of time on my part...)

Very happily, it turns our that with repeated testing I can no longer get such
large regressions. In fact it looks like hg 1.7.1 is slightly faster than hg
1.5.4 for me. This is great news!

So the details:  In my testing I can't always get stable times. I have seen the
first execution in a series go some 30% slower sometimes but then after repeated
runs things speed up.  I don't know how to reliably reproduce this, so I guess
its best to ignore this data point for now. (In the results below I include one
such example of this different timing...)

For instance these are some tests I run. chg is just the local mercurial of
MacHg with the following env settings for the shell...

		[newEnv copyValueOfKey:@"SSH_ASKPASS"	from:processEnv];
		[newEnv copyValueOfKey:@"SSH_AUTH_SOCK"	from:processEnv];
		[newEnv copyValueOfKey:@"HOME"			from:processEnv];
		[newEnv copyValueOfKey:@"PATH"			from:processEnv];
		[newEnv copyValueOfKey:@"TMPDIR"		from:processEnv];
		[newEnv copyValueOfKey:@"USER"			from:processEnv];
		[newEnv setObject:localMercurialPath	 forKey:@"PYTHONPATH"];
		[newEnv setObject:executableLocationHG() forKey:@"HG"];
		[newEnv setObject:@"UTF-8"  forKey:@"HGENCODING"];
		[newEnv setObject:@"1"		forKey:@"HGPLAIN"];

Larger Repo (open office)
------------------------------
For now on larger projects I am only seeing something like a 5% regression in 1.5.4->1.6.4 and happily it seems to now be corrected in 1.7.1 which now happily seems faster for large repositories than previous versions.

[Bolt:QuickSilver/Development/sandbox/openOffice] openOffice 262741(262741) $ chg version
Mercurial Distributed SCM (version 1.5.4+20100601)
[Bolt:QuickSilver/Development/sandbox/openOffice] openOffice 262741(262741) $ time hg status --all > /dev/null
run 1:  real 0m3.589s  user 0m1.309s  sys 0m2.227s
run 2:  real 0m3.532s  user 0m1.305s  sys 0m2.196s
run 3:  real 0m3.532s  user 0m1.308s  sys 0m2.193s
run 4:  real 0m3.539s  user 0m1.305s  sys 0m2.204s
run 5:  real 0m3.532s  user 0m1.304s  sys 0m2.197s

[Bolt:QuickSilver/Development/sandbox/openOffice] openOffice 262741(262741) $ chg version
Mercurial Distributed SCM (version 1.6.4+20101001)
[Bolt:QuickSilver/Development/sandbox/openOffice] openOffice 262741(262741) $ time chg status --all > /dev/null
run 1: real 0m3.741s  user 0m1.488s  sys 0m2.203s
run 2: real 0m3.751s  user 0m1.482s  sys 0m2.220s
run 3: real 0m3.769s  user 0m1.491s  sys 0m2.245s
run 4: real 0m3.735s  user 0m1.489s  sys 0m2.211s
run 5: real 0m3.738s  user 0m1.489s  sys 0m2.215s

[Bolt:QuickSilver/Development/sandbox/openOffice] openOffice 262741(262741) $ chg version
Mercurial Distributed SCM (version 1.7.1+20101116)
[Bolt:QuickSilver/Development/sandbox/openOffice] openOffice 262741(262741) $ time chg status --all > /dev/null
run 1: real 0m3.446s  user 0m1.166s  sys 0m2.213s
run 2: real 0m3.414s  user 0m1.168s  sys 0m2.174s
run 3: real 0m3.417s  user 0m1.171s  sys 0m2.178s
run 4: real 0m3.396s  user 0m1.167s  sys 0m2.172s
run 5: real 0m3.377s  user 0m1.165s  sys 0m2.169s

However to indicate I had strange timings you can see the following:

[Bolt:QuickSilver/Development/sandbox/openOffice] openOffice 262741(262741) $ chg version
Mercurial Distributed SCM (version 1.7+20101101)
[Bolt:QuickSilver/Development/sandbox/openOffice] openOffice 262741(262741) $ time chg status --all > /dev/null
run 1: real 0m3.803s  user 0m1.557s  sys 0m2.105s
run 2: real 0m3.156s  user 0m1.531s  sys 0m1.607s
run 3: real 0m3.587s  user 0m1.546s  sys 0m2.020s
run 4: real 0m3.151s  user 0m1.531s  sys 0m1.603s
run 5: real 0m3.525s  user 0m1.536s  sys 0m1.965s
run 6: real 0m3.052s  user 0m1.517s  sys 0m1.531s

Note the oscillation in times. (the sys times are suspiciously changing in these runs). Perhaps one of the crew members has a better idea of what is happening here?

And so here is another example of the same tests I just ran again some 8 hours later (Which are around 30% faster than the previous tests of the same repo with the same version of Mercurial):

[Bolt:QuickSilver/Development/sandbox/openOffice] openOffice 262741(262741) ⌘ chg version
Mercurial Distributed SCM (version 1.7.1+20101116)
[Bolt:QuickSilver/Development/sandbox/openOffice] openOffice 262741(262741) ⌘ time chg status --all > /dev/null

run 1: real 0m2.819s    user 0m1.144s    sys 0m1.516s
run 2: real 0m3.986s    user 0m1.153s    sys 0m1.786s
run 3: real 0m2.599s    user 0m1.140s    sys 0m1.445s
run 4: real 0m2.953s    user 0m1.152s    sys 0m1.794s
run 5: real 0m2.606s    user 0m1.143s    sys 0m1.450s
run 6: real 0m2.997s    user 0m1.152s    sys 0m1.795s

Smaller repo
-----------------

In a smaller repo at this stage I am only able to reproduce a 12% regression in 1.5.4->1.7 and again happily for 1.7.1 things seem to be about the same speed as 1.5.4 again.

[Bolt:/Development/MacHgDev/MacHgSource] MacHgSource 430(430) $ chg version
Mercurial Distributed SCM (version 1.5.4+20100601)
[Bolt:/Development/MacHgDev/MacHgSource] MacHgSource 430(430) $ time chg status --all > /dev/null
run 1: real 0m0.113s  user 0m0.078s  sys 0m0.033s
run 2: real 0m0.110s  user 0m0.077s  sys 0m0.032s
run 3: real 0m0.110s  user 0m0.077s  sys 0m0.031s
run 4: real 0m0.110s  user 0m0.077s  sys 0m0.031s
run 5: real 0m0.110s  user 0m0.077s  sys 0m0.032s

Bolt:/Development/MacHgDev/MacHgSource] MacHgSource 430(430) $ chg version
Mercurial Distributed SCM (version 1.7+20101101)
(see http://mercurial.selenic.com for more information)
[Bolt:/Development/MacHgDev/MacHgSource] MacHgSource 430(430) $ time chg status --all > /dev/null
run 1: real 0m0.129s  user 0m0.091s  sys 0m0.037s
run 2: real 0m0.126s  user 0m0.089s  sys 0m0.037s
run 3: real 0m0.123s  user 0m0.089s  sys 0m0.034s
run 4: real 0m0.124s  user 0m0.089s  sys 0m0.035s
run 5: real 0m0.123s  user 0m0.089s  sys 0m0.034s

[Bolt:/Development/MacHgDev/MacHgSource] MacHgSource 430(430) $ chg version
Mercurial Distributed SCM (version 1.7.1+20101116)
[Bolt:/Development/MacHgDev/MacHgSource] MacHgSource 430(430) $ time chg status --all > /dev/null
run 1: real 0m0.115s  user 0m0.076s  sys 0m0.038s
run 2: real 0m0.110s  user 0m0.072s  sys 0m0.037s
run 3: real 0m0.110s  user 0m0.072s  sys 0m0.036s
run 4: real 0m0.109s  user 0m0.072s  sys 0m0.036s
run 5: real 0m0.111s  user 0m0.073s  sys 0m0.037s
run 6: real 0m0.110s  user 0m0.072s  sys 0m0.036s

-------------------

In conclusion I think I must have had some background processes going on during these tests. I looked at top and other stats but nothing stuck out... Anyway since I can't get reliable timings here I don't know if there is anything to investigate for you here...

Cheers,
   Jas