Hideously slow VC status queries fixed

Hideously slow VC status queries fixed

[Eric S. Raymond]

It gives me great pleasure to be able to announce that I have found,
and fixed, the bug that made C-x v d so godawful much slower than the
underlying commands.

This one was a truly classic collision of blunders.  It should be a
warning to us all about the perils of the expedient local hack.

When I originally wrote VC mode back in the dark and backward abysm of
time, it was for RCS and SCCS.  Back then there was no dir-state hook;
vc-dired-hook queried the version-control status of each file named in
the VC-dired buffer individually.  This performed acceptably because
code directories averaged far smaller then.

Whoever wrote the first dir-state hook (probably for CVS) blundered
badly by making the most conservative possible modification to
vc-dired.  That unknown hacker, may his name be accursed, used
dir-state *only for subdirectories*; the status of all files in
default-directory was still queried one at a time.  He carefully wrote
the dir-state hook to use "status -l", not recursing down
subdirectories, because he gathered all the subdirectories by walking
through the dired listing and applied the dir-state method to each
one at a time.

People who wrote backends for later VCSes followed suit, so focused
on getting their backends minimally working that they failed to notice
that the upper-level logic was perversely misdesigned. 

And this threw away a lot of data; most of the later back ends are
like SVN in there's no way to tell the status command not to recurse
down directories.  So the status information for the *entire file
tree* would get queried and parsed as many times as there were
non-excluded directory nodes in the tree.

Gaaaahhhhh...no *wonder* it was slower than a snail on Quaaludes!

All I did to fix this was notice that you *want* dir-state hook to
recurse down directory tries -- and then call it exactly once on
default-directory.  Most of the fix consisted of removing options
to suppress the recursion and documenting the new expected behavior
of dir-state.

Someone should have noticed this a lot sooner.
-- 
		<a href="http://www.catb.org/~esr/">Eric S. Raymond</a>

What, then is law [government]? It is the collective organization of
the individual right to lawful defense."
	-- Frederic Bastiat, "The Law"

Re: Hideously slow VC status queries fixed

[Tom Tromey]

>>>>> "Eric" == Eric S Raymond <esr@snark.thyrsus.com> writes:

Eric> It gives me great pleasure to be able to announce that I have found,
Eric> and fixed, the bug that made C-x v d so godawful much slower than the
Eric> underlying commands.

Nice.  The speed of vc-dired is one reason I'm still using pcl-cvs
(and the un-bundled psvn) for everything.

I optimistically tried the new vc-dired on my killer test case: gcc.
I didn't try the whole trunk (since that is just way too big), but I
tried on 'trunk/gcc' -- unlike running on the whole trunk, this is a
reasonable thing to want to do since most hacking takes place here.

After a few minutes I got this:

    Warning (undo): Buffer `gcc' undo info was 3023389 bytes long.
    The undo info was discarded because it exceeded `undo-outer-limit'.

At that point I interrupted it.

'svn status' in gcc/trunk takes less than a second (when warm -- true
in both these tests).  'svn status -v' takes 12 seconds when printing
to gnome-terminal, less than 2 seconds when printing to 'wc'.

I don't know whether vc-dired is expected to scale to a working
directory with 26,499 files underneath it.  I sure wish it would :-).
FWIW neither pcl-cvs nor psvn handles this case very well either (the
psvn author helpfully provided some ideas for tweaking it, which I
haven't attempted yet).

Tom

Re: Hideously slow VC status queries fixed

[Eric S. Raymond]

Tom Tromey <tromey@redhat.com>:
> Eric> It gives me great pleasure to be able to announce that I have found,
> Eric> and fixed, the bug that made C-x v d so godawful much slower than the
> Eric> underlying commands.
> 
> Nice.  The speed of vc-dired is one reason I'm still using pcl-cvs
> (and the un-bundled psvn) for everything.
> 
> I optimistically tried the new vc-dired on my killer test case: gcc.
> I didn't try the whole trunk (since that is just way too big), but I
> tried on 'trunk/gcc' -- unlike running on the whole trunk, this is a
> reasonable thing to want to do since most hacking takes place here.
> 
> After a few minutes I got this:
> 
>     Warning (undo): Buffer `gcc' undo info was 3023389 bytes long.
>     The undo info was discarded because it exceeded `undo-outer-limit'.

Yeah.  What's clearly happening there is that it's generating a
*monstar* status listing recursing down all those directories.  The
resulting output is big enough to strain Emacs's innards.  There ain't
much I, as a mode author, can do about that.
 
> I don't know whether vc-dired is expected to scale to a working
> directory with 26,499 files underneath it.  I sure wish it would :-).

vc-dired will scale as well as Emacs scales (he said, a bit evasively.)

I don't think the bottlneck is VC anymore.  In the normal cases (CVS, 
SVN, Mercurial), VC now generates just one (1) command.  I suppose
parsing time could be an issue -- has anyone profiled 26,499 regexp
matches lately ?

I know this: C-x v l is now *fast* on normal-sized SVN, CVS, and Mercurial
directories.   It sure wasn't before.
-- 
		<a href="http://www.catb.org/~esr/">Eric S. Raymond</a>

Re: Hideously slow VC status queries fixed

[Richard Stallman]

    parsing time could be an issue -- has anyone profiled 26,499 regexp
    matches lately ?

The speed of regexp matching depends greatly on the regexp itself.
If that regexp is slow, perhaps there is a much faster way
to parse that data.

Just turning off undo during the initial creation of that buffer's
contents will also speed it up somewhat, but I don't know if that is
significant.

Re: Hideously slow VC status queries fixed

[Tom Tromey]

>>>>> "Eric" == Eric S Raymond <esr@thyrsus.com> writes:

Eric> I don't think the bottlneck is VC anymore.  In the normal cases (CVS, 
Eric> SVN, Mercurial), VC now generates just one (1) command.  I suppose
Eric> parsing time could be an issue -- has anyone profiled 26,499 regexp
Eric> matches lately ?

I looked at this a little bit.

Here's the top of the elp output (any function after this took less
than 1 second elapsed time).  I used elp-instrument-package with "vc-"
as the argument (I never used elp before; let me know if I did
something wrong).

Function Name                        Call Count  Elapsed Time  Average Time
===================================  ==========  ============  ============
vc-call-backend                      346         31.258875999  0.0903435722
vc-backend                           25650       15.846656999  0.0006178033
vc-registered                        34          8.9951210000  0.2645623823
vc-stay-local-p                      1           7.837376      7.837376
vc-file-getprop                      51331       7.2145619999  0.0001405498
vc-file-setprop                      238371      6.6009059999  2.769...e-05
vc-state                             25613       2.4212969999  9.453...e-05


Interestingly, vc-svn doesn't show up here at all.


I also looked at this with oprofile.  This is interesting too:

samples  %        image name               symbol name
1695163  48.2143  emacs                    Fbyte_code
295864    8.4150  emacs                    arithcompare
238998    6.7976  emacs                    mark_object

Regular expression matching comes in at #13:

31889     0.9070  emacs                    re_match_2_internal

What this says to me is that we're simply running a lot of plain emacs
lisp, and that regex matching is not a big problem here.  (I can send
the whole list if you are interested.)


I wonder if there is a way to do a lot less work.  For instance, could
we have VC look only at files that are not 'up-to-date?  In my tree
this would mean processing 24 files -- 3 orders of magnitude fewer.  I
think this would be a pretty common result for large trees, since it
is rare to have a patch that touches a substantial fraction of gcc.

Thank you for working on this.  I appreciate it quite a bit.

Tom

Re: Hideously slow VC status queries fixed

[Eric S. Raymond]

Tom Tromey <tromey@redhat.com>:
> What this says to me is that we're simply running a lot of plain emacs
> lisp, and that regex matching is not a big problem here.

That is very valuable information, thank you.

>                                                         (I can send
> the whole list if you are interested.)

I'm not.  It looks like you're good enough at collecting and
interpreting those numbers that I don't need to be.  And, frankly, I
like having someone else do that -- you're likely to spot things I
might miss because I'm not seeing past my assumptions.

I'm going to do another rewrite of vc-dired-hook shortly, and I'd
appreciate it if you'd profile the results and compare those numbers
against the baseline you've established.

> I wonder if there is a way to do a lot less work.  For instance, could
> we have VC look only at files that are not 'up-to-date?  In my tree
> this would mean processing 24 files -- 3 orders of magnitude fewer.  I
> think this would be a pretty common result for large trees, since it
> is rare to have a patch that touches a substantial fraction of gcc.

I think that you are not quite understanding the problem here -- or at
least my assumptions about what constitutes "less work" (while
possibly incorrect) are quite different from yours.

Terminological note: by "the VC status command" I mean "svn status" or
"hg status" or whatever.  The thing that VC mode catures output from
and parses.

First, I assume that the time for the underlying VC status command to collect
its information is roughly constant, independent of the verbosity level
of the report.  It has to grovel through the same data structures 
either way -- its verbosity options only controls what it dumps to
standard out.

Second assumption: to make VC-Dired refresh quickly, the main thing we
need to avoid is lots of client/server round trips -- or, assuming
we're staying local, lots of individual status-command executions.
Either way, this pushes us towards relying on one big report from one
VC status command execution.

By contrast, I think the size of the data returned by the VC status
command, and the parsing time required for VC mode to pull that data
into Lisp-space, is much less significant.  Or, to put it a different
way, I'm assuming that the startup latency of the report generator(s)
dominates the total time from the C-x v d keystroke to the display
refresh.

Under these assumption, trying to make the VC status command look at fewer
files doesn't make a lot of sense -- it won't save any executio time,
if assumption #1 is true.  And if we don't capture the complete
VC state of the tree during the dir-state call at the beginning of
vc-dired-hook, we're just going to have to do more expensive round
trips later, during the remainder of vc-dired-hook, to get the missing
information. By assumption #2 this would be a big lose.

(In fact it's doing that kind of multiple-round-trip patch-up now, which is 
what I hope to eliminate in the upcoming rewrite.)

Your report that regexp-matching time doesn't dominate appears to confirm
my theory. If you can find a way to crunch your profiling data that 
separates the latency cost of getting the report from the rest of the
interpretation time, it would be useful to compare the two.

> Thank you for working on this.  I appreciate it quite a bit.

You are welcome, and I am in turn grateful for the profiling data.  
Since I'm trying to optimize for performance, those numbers are the
most valuable guidance I can have.
-- 
		<a href="http://www.catb.org/~esr/">Eric S. Raymond</a>

Re: Hideously slow VC status queries fixed

[Tom Tromey]

>>>>> "Eric" == Eric S Raymond <esr@thyrsus.com> writes:

Eric> I'm going to do another rewrite of vc-dired-hook shortly, and I'd
Eric> appreciate it if you'd profile the results and compare those numbers
Eric> against the baseline you've established.

No problem.

>> I wonder if there is a way to do a lot less work.  For instance, could
>> we have VC look only at files that are not 'up-to-date?  In my tree
>> this would mean processing 24 files -- 3 orders of magnitude fewer.  I
>> think this would be a pretty common result for large trees, since it
>> is rare to have a patch that touches a substantial fraction of gcc.

Eric> I think that you are not quite understanding the problem here -- or at
Eric> least my assumptions about what constitutes "less work" (while
Eric> possibly incorrect) are quite different from yours.

Yeah, I'm sure I don't understand :-).  More on this below.

Eric> By contrast, I think the size of the data returned by the VC status
Eric> command, and the parsing time required for VC mode to pull that data
Eric> into Lisp-space, is much less significant.  Or, to put it a different
Eric> way, I'm assuming that the startup latency of the report generator(s)
Eric> dominates the total time from the C-x v d keystroke to the display
Eric> refresh.

Eric> If you can find a way to crunch your profiling data that
Eric> separates the latency cost of getting the report from the rest
Eric> of the interpretation time, it would be useful to compare the
Eric> two.

I think there is something to this, but it is not the whole picture.

I timed 'svn status -v' on gcc:

opsy. /usr/bin/time svn status -v > /dev/null
0.95user 1.13system 0:16.79elapsed 12%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (37major+6120minor)pagefaults 0swaps

However, this is with a cold cache.  With a warm cache it is
dramatically different:

opsy. /usr/bin/time svn status -v > /dev/null
0.90user 0.33system 0:01.28elapsed 96%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+6157minor)pagefaults 0swaps


I also tried it on a much smaller tree I have sitting around:

opsy. /usr/bin/time svn status -v > /dev/null
0.02user 0.04system 0:01.61elapsed 4%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+740minor)pagefaults 0swaps

So we can clearly see here that svn is just a lot slower on a big
tree, at least when cold.  This confirms part of your theory.


However, I also tried this:

    (let ((zz-s-time (current-time)))
      (vc-directory "~/gnu/Trunk/trunk/gcc/" nil)
       (time-subtract (current-time) zz-s-time))
   
This yielded (0 320 260248) with a warm cache -- so I think most of
the time must be in Emacs processing, not in svn.  Even with a cold
cache this number would be very bad.


I think what I don't understand is why we run 'svn status -v'.  This
will print information about every file.  But, why do we need
information about every file?  Would it be possible to only deal with
files that aren't "up-to-date", i.e., omit the '-v'?  This would seem
to be much more efficient.

That's just an idea though.  I also don't understand everything that
is going on in the elp results, like where all those calls to
vc-call-backend come from.

Tom

Re: Hideously slow VC status queries fixed

[Eric S. Raymond]

Tom Tromey <tromey@redhat.com>:
> This yielded (0 320 260248) with a warm cache -- so I think most of
> the time must be in Emacs processing, not in svn.  Even with a cold
> cache this number would be very bad.

Agreed.
 
> I think what I don't understand is why we run 'svn status -v'.  This
> will print information about every file.  But, why do we need
> information about every file?  Would it be possible to only deal with
> files that aren't "up-to-date", i.e., omit the '-v'?  This would seem
> to be much more efficient.

That will do only when (a) we're in terse mode, and (b) we don't want to
see unregistered files.  Otherwise we need -v.

Maybe dir-state should take a verbosity-level argument?  I'll look into this.
 
> That's just an idea though.  I also don't understand everything that
> is going on in the elp results, like where all those calls to
> vc-call-backend come from.

I'm pretty sure I know where those are.  I expect to remove the line
of code that's generating them soon.
-- 
		<a href="http://www.catb.org/~esr/">Eric S. Raymond</a>

Re: Hideously slow VC status queries fixed

[Tom Tromey]

>>>>> "Eric" == Eric S Raymond <esr@thyrsus.com> writes:

Eric> That will do only when (a) we're in terse mode, and (b) we don't want to
Eric> see unregistered files.  Otherwise we need -v.

Good point.  I never remember non-terse mode... but then I haven't
been a heavy vc-dired user, due to speed :)

>> That's just an idea though.  I also don't understand everything that
>> is going on in the elp results, like where all those calls to
>> vc-call-backend come from.

Eric> I'm pretty sure I know where those are.  I expect to remove the line
Eric> of code that's generating them soon.

Appended is a call-graph profile, thanks to Christian Ohler.
This is pretty interesting.

Tom

Function Name                        Call Count  Elapsed Time  Average Time
===================================  ==========  ============  ============
  vc-registered                       363         1435.5771489  3.9547579862
vc-call-backend                     376         4531.5646809  12.052033726
  <self or not profiled>              376         3089.8385159  8.2176556276
  vc-stay-local-p                     1           1422.384572   1422.384572
  vc-file-setprop                     238490      10.425457000  4.371...e-05
  vc-sccs-registered                  36          2.919531      0.0810980833
  vc-default-registered               37          2.2229139999  0.0600787567
  vc-hg-registered                    36          0.7906200000  0.0219616666
  vc-git-registered                   36          0.784571      0.0217936388
  vc-mcvs-registered                  36          0.7820339999  0.0217231666
  vc-mtn-registered                   36          0.5590209999  0.0155283611
  vc-bzr-registered                   36          0.3502429999  0.0097289722
  vc-arch-registered                  36          0.347461      0.0096516944
  vc-find-backend-function            6           0.070114      0.0116856666
  vc-working-revision                 5           0.044984      0.0089968000
  vc-state                            5           0.044193      0.0088386
  vc-file-getprop                     34          0.0002640000  7.764...e-06
  vc-kill-buffer-hook                 35          0.0001860000  5.314...e-06

  vc-stay-local-p                     1           1422.366707   1422.366707
vc-backend                          25667       1787.1615969  0.0696287683
  vc-registered                       37          1441.2173279  38.951819675
  <self or not profiled>              25667       339.20715399  0.0132156915
  vc-file-getprop                     25668       6.7371149999  0.0002624713

  vc-backend                          37          1441.2173279  38.951819675
vc-registered                       37          1441.2173279  38.951819675
  vc-call-backend                     363         1435.5771489  3.9547579862
  <self or not profiled>              37          5.6396360000  0.1524225945
  vc-file-setprop                     37          0.000325      8.783...e-06
  vc-file-getprop                     37          0.0002180000  5.891...e-06

  vc-call-backend                     1           1422.384572   1422.384572
vc-stay-local-p                     1           1422.384572   1422.384572
  vc-backend                          1           1422.366707   1422.366707
  <self or not profiled>              1           0.0178510000  0.0178510000
  vc-make-backend-sym                 1           1.4e-05       1.4e-05

  vc-call-backend                     5           0.044193      0.0088386
vc-state                            25630       338.47379800  0.0132061567
  <self or not profiled>              25630       332.66181800  0.0129793920
  vc-file-getprop                     25630       5.8119799999  0.0002267647

  vc-backend                          25668       6.7371149999  0.0002624713
  vc-state                            25630       5.8119799999  0.0002267647
  vc-working-revision                 5           0.000611      0.0001222
  vc-call-backend                     34          0.0002640000  7.764...e-06
  vc-registered                       37          0.0002180000  5.891...e-06
vc-file-getprop                     51374       12.550188000  0.0002442906
  <self or not profiled>              51374       12.550188000  0.0002442906

  vc-call-backend                     238490      10.425457000  4.371...e-05
  vc-registered                       37          0.000325      8.783...e-06
vc-file-setprop                     238527      10.425782000  4.370...e-05
  <self or not profiled>              238527      10.425782000  4.370...e-05

  vc-sccs-registered                  36          2.596495      0.0721248611
  vc-call-backend                     37          2.2229139999  0.0600787567
vc-default-registered               73          4.819409      0.0660193013
  vc-check-master-templates           73          3.312153      0.0453719589
  <self or not profiled>              73          1.5062270000  0.0206332465
  vc-make-backend-sym                 73          0.001029      1.409...e-05

  vc-default-registered               73          3.312153      0.0453719589
vc-check-master-templates           73          3.312153      0.0453719589
  <self or not profiled>              73          2.980151      0.0408239863
  vc-possible-master                  219         0.3320019999  0.0015159908

  vc-call-backend                     36          2.919531      0.0810980833
vc-sccs-registered                  36          2.919531      0.0810980833
  vc-default-registered               36          2.596495      0.0721248611
  <self or not profiled>              36          0.3230360000  0.0089732222

  vc-call-backend                     36          0.7906200000  0.0219616666
vc-hg-registered                    36          0.7906200000  0.0219616666
  <self or not profiled>              36          0.7592740000  0.0210909444
  vc-find-root                        36          0.031346      0.0008707222

  vc-call-backend                     36          0.784571      0.0217936388
vc-git-registered                   36          0.784571      0.0217936388
  <self or not profiled>              36          0.752849      0.0209124722
  vc-find-root                        36          0.031722      0.0008811666

  vc-call-backend                     36          0.7820339999  0.0217231666
vc-mcvs-registered                  36          0.7820339999  0.0217231666
  <self or not profiled>              36          0.7508869999  0.0208579722
  vc-find-root                        36          0.031147      0.0008651944

  vc-call-backend                     36          0.5590209999  0.0155283611
vc-mtn-registered                   36          0.5590209999  0.0155283611
  <self or not profiled>              36          0.5279159999  0.0146643333
  vc-find-root                        36          0.0311050000  0.0008640277

  vc-call-backend                     36          0.3502429999  0.0097289722
vc-bzr-registered                   36          0.3502429999  0.0097289722
  <self or not profiled>              36          0.3166469999  0.0087957499
  vc-find-root                        36          0.0335959999  0.0009332222

  vc-call-backend                     36          0.347461      0.0096516944
vc-arch-registered                  36          0.347461      0.0096516944
  <self or not profiled>              36          0.3156090000  0.0087669166
  vc-find-root                        36          0.0318520000  0.0008847777

  vc-check-master-templates           219         0.3320019999  0.0015159908
vc-possible-master                  219         0.3320019999  0.0015159908
  <self or not profiled>              219         0.3312209999  0.0015124246
  vc-sccs-search-project-dir          36          0.000781      2.169...e-05

  vc-bzr-registered                   36          0.0335959999  0.0009332222
  vc-arch-registered                  36          0.0318520000  0.0008847777
  vc-git-registered                   36          0.031722      0.0008811666
  vc-hg-registered                    36          0.031346      0.0008707222
  vc-mcvs-registered                  36          0.031147      0.0008651944
  vc-mtn-registered                   36          0.0311050000  0.0008640277
vc-find-root                        216         0.1907680000  0.0008831851
  <self or not profiled>              216         0.1907680000  0.0008831851

  vc-call-backend                     6           0.070114      0.0116856666
vc-find-backend-function            7           0.0788049999  0.0112578571
  <self or not profiled>              7           0.0787069999  0.0112438571
  vc-make-backend-sym                 7           9.8e-05       1.4e-05

  vc-call-backend                     5           0.044984      0.0089968000
vc-working-revision                 5           0.044984      0.0089968000
  <self or not profiled>              5           0.044373      0.0088746
  vc-file-getprop                     5           0.000611      0.0001222

  vc-default-registered               73          0.001029      1.409...e-05
  vc-find-backend-function            7           9.8e-05       1.4e-05
  vc-stay-local-p                     1           1.4e-05       1.4e-05
vc-make-backend-sym                 81          0.0011409999  1.408...e-05
  <self or not profiled>              81          0.0011409999  1.408...e-05

  vc-possible-master                  36          0.000781      2.169...e-05
vc-sccs-search-project-dir          36          0.000781      2.169...e-05
  <self or not profiled>              36          0.000781      2.169...e-05

  vc-call-backend                     35          0.0001860000  5.314...e-06
vc-kill-buffer-hook                 36          0.0001900000  5.277...e-06
  <self or not profiled>              36          0.0001900000  5.277...e-06

Re: Hideously slow VC status queries fixed

[Eric S. Raymond]

Tom Tromey <tromey@redhat.com>:
> Appended is a call-graph profile, thanks to Christian Ohler.
> This is pretty interesting.

What are you seeing that I'm not?  Nothing jumps out at me as 
peculiar.
-- 
		<a href="http://www.catb.org/~esr/">Eric S. Raymond</a>

Re: Hideously slow VC status queries fixed

[Dan Nicolaescu]

"Eric S. Raymond" <esr@thyrsus.com> writes:

  > Tom Tromey <tromey@redhat.com>:
  > > Appended is a call-graph profile, thanks to Christian Ohler.
  > > This is pretty interesting.
  > 
  > What are you seeing that I'm not?  Nothing jumps out at me as 
  > peculiar.


Function Name                        Call Count  Elapsed Time  Average Time
===================================  ==========  ============  ============
  vc-registered                       363         1435.5771489  3.9547579862
vc-call-backend                     376         4531.5646809  12.052033726
  <self or not profiled>              376         3089.8385159  8.2176556276
  vc-stay-local-p                     1           1422.384572   1422.384572
                                                  ^^^^^^^^
                                                  The time here seems to be
                                                  too high.

Re: Hideously slow VC status queries fixed

[Eric S. Raymond]

Dan Nicolaescu <dann@ics.uci.edu>:
> "Eric S. Raymond" <esr@thyrsus.com> writes:
> 
>   > Tom Tromey <tromey@redhat.com>:
>   > > Appended is a call-graph profile, thanks to Christian Ohler.
>   > > This is pretty interesting.
>   > 
>   > What are you seeing that I'm not?  Nothing jumps out at me as 
>   > peculiar.
> 
> 
> Function Name                        Call Count  Elapsed Time  Average Time
> ===================================  ==========  ============  ============
>   vc-registered                       363         1435.5771489  3.9547579862
> vc-call-backend                     376         4531.5646809  12.052033726
>   <self or not profiled>              376         3089.8385159  8.2176556276
>   vc-stay-local-p                     1           1422.384572   1422.384572
>                                                   ^^^^^^^^
>                                                   The time here seems to be
>                                                   too high.

Interesting. I'll look into this.
-- 
		<a href="http://www.catb.org/~esr/">Eric S. Raymond</a>

Re: Hideously slow VC status queries fixed

[Tom Tromey]

>>>>> "Eric" == Eric S Raymond <esr@thyrsus.com> writes:

Eric> Tom Tromey <tromey@redhat.com>:
>> Appended is a call-graph profile, thanks to Christian Ohler.
>> This is pretty interesting.

Eric> What are you seeing that I'm not?  Nothing jumps out at me as 
Eric> peculiar.

The vc-registered -> vc-call-backend edge seems particularly bad.
But perhaps I'm misreading this, or we knew it, or this profiler is
giving erroneous results.

BTW, today's VC changes roughly halved the number of calls to
vc-call-backend, but (according to oelp) the elapsed time hasn't
changed much.  New profile appended.

Tom

Function Name                        Call Count  Elapsed Time  Average Time
===================================  ==========  ============  ============
  vc-registered                       173         1366.0392379  7.8961805664
vc-call-backend                     186         4515.3948180  24.276316225
  <self or not profiled>              186         3140.0213510  16.881835220
  vc-stay-local-p                     1           1359.762977   1359.762977
  vc-file-setprop                     238528      11.230348000  4.708...e-05
  vc-default-registered               18          1.501319      0.0834066111
  vc-sccs-registered                  17          1.4998170000  0.0882245294
  vc-git-registered                   17          0.3869679999  0.0227628235
  vc-mcvs-registered                  17          0.175918      0.0103481176
  vc-bzr-registered                   17          0.166246      0.0097791764
  vc-hg-registered                    17          0.1651839999  0.0097167058
  vc-arch-registered                  17          0.1644719999  0.0096748235
  vc-mtn-registered                   17          0.163277      0.0096045294
  vc-find-backend-function            6           0.068498      0.0114163333
  vc-state                            5           0.0450599999  0.009012
  vc-working-revision                 5           0.043155      0.008631
  vc-file-getprop                     15          0.0001360000  9.066...e-06
  vc-kill-buffer-hook                 16          9.199...e-05  5.749...e-06

  vc-stay-local-p                     1           1359.745306   1359.745306
  vc-state                            17          9.137986      0.5375285882
vc-backend                          23          1368.9283529  59.518624043
  vc-registered                       18          1368.5600880  76.031116000
  <self or not profiled>              23          0.3674779999  0.0159773043
  vc-file-getprop                     24          0.000787      3.279...e-05

  vc-backend                          18          1368.5600880  76.031116000
vc-registered                       18          1368.5600880  76.031116000
  vc-call-backend                     173         1366.0392379  7.8961805664
  <self or not profiled>              18          2.5205340000  0.1400296666
  vc-file-setprop                     18          0.000171      9.5e-06
  vc-file-getprop                     18          0.000145      8.055...e-06

  vc-call-backend                     1           1359.762977   1359.762977
vc-stay-local-p                     1           1359.762977   1359.762977
  vc-backend                          1           1359.745306   1359.745306
  <self or not profiled>              1           0.0176510000  0.0176510000
  vc-make-backend-sym                 1           2e-05         2e-05

  vc-call-backend                     5           0.0450599999  0.009012
vc-state                            51291       680.21053799  0.0132617913
  <self or not profiled>              51291       658.54704799  0.0128394269
  vc-file-getprop                     51291       12.525504000  0.0002442047
  vc-backend                          17          9.137986      0.5375285882

  vc-state                            51291       12.525504000  0.0002442047
  vc-backend                          24          0.000787      3.279...e-05
  vc-working-revision                 5           0.000702      0.0001404
  vc-registered                       18          0.000145      8.055...e-06
  vc-call-backend                     15          0.0001360000  9.066...e-06
vc-file-getprop                     51353       12.527274000  0.0002439443
  <self or not profiled>              51353       12.527274000  0.0002439443

  vc-call-backend                     238528      11.230348000  4.708...e-05
  vc-registered                       18          0.000171      9.5e-06
vc-file-setprop                     238546      11.230519000  4.707...e-05
  <self or not profiled>              238546      11.230519000  4.707...e-05

  vc-call-backend                     18          1.501319      0.0834066111
  vc-sccs-registered                  17          1.3520339999  0.0795314117
vc-default-registered               35          2.853353      0.0815243714
  vc-check-master-templates           35          2.0015959999  0.0571884571
  <self or not profiled>              35          0.8511960000  0.0243198857
  vc-make-backend-sym                 35          0.0005610000  1.602...e-05

  vc-default-registered               35          2.0015959999  0.0571884571
vc-check-master-templates           35          2.0015959999  0.0571884571
  <self or not profiled>              35          1.8503919999  0.0528683428
  vc-possible-master                  105         0.151204      0.0014400380

  vc-call-backend                     17          1.4998170000  0.0882245294
vc-sccs-registered                  17          1.4998170000  0.0882245294
  vc-default-registered               17          1.3520339999  0.0795314117
  <self or not profiled>              17          0.1477830000  0.0086931176

  vc-call-backend                     17          0.3869679999  0.0227628235
vc-git-registered                   17          0.3869679999  0.0227628235
  <self or not profiled>              17          0.3711519999  0.0218324705
  vc-find-root                        17          0.015816      0.0009303529

  vc-call-backend                     17          0.175918      0.0103481176
vc-mcvs-registered                  17          0.175918      0.0103481176
  <self or not profiled>              17          0.1591679999  0.0093628235
  vc-find-root                        17          0.0167500000  0.0009852941

  vc-call-backend                     17          0.166246      0.0097791764
vc-bzr-registered                   17          0.166246      0.0097791764
  <self or not profiled>              17          0.149044      0.0087672941
  vc-find-root                        17          0.017202      0.0010118823

  vc-call-backend                     17          0.1651839999  0.0097167058
vc-hg-registered                    17          0.1651839999  0.0097167058
  <self or not profiled>              17          0.1492689999  0.0087805294
  vc-find-root                        17          0.015915      0.0009361764

  vc-call-backend                     17          0.1644719999  0.0096748235
vc-arch-registered                  17          0.1644719999  0.0096748235
  <self or not profiled>              17          0.1479379999  0.0087022352
  vc-find-root                        17          0.016534      0.0009725882

  vc-call-backend                     17          0.163277      0.0096045294
vc-mtn-registered                   17          0.163277      0.0096045294
  <self or not profiled>              17          0.1464970000  0.0086174705
  vc-find-root                        17          0.01678       0.0009870588

  vc-check-master-templates           105         0.151204      0.0014400380
vc-possible-master                  105         0.151204      0.0014400380
  <self or not profiled>              105         0.150816      0.0014363428
  vc-sccs-search-project-dir          17          0.000388      2.282...e-05

  vc-bzr-registered                   17          0.017202      0.0010118823
  vc-mtn-registered                   17          0.01678       0.0009870588
  vc-mcvs-registered                  17          0.0167500000  0.0009852941
  vc-arch-registered                  17          0.016534      0.0009725882
  vc-hg-registered                    17          0.015915      0.0009361764
  vc-git-registered                   17          0.015816      0.0009303529
vc-find-root                        102         0.0989970000  0.0009705588
  <self or not profiled>              102         0.0989970000  0.0009705588

  vc-call-backend                     6           0.068498      0.0114163333
vc-find-backend-function            7           0.076992      0.0109988571
  <self or not profiled>              7           0.076893      0.0109847142
  vc-make-backend-sym                 7           9.900...e-05  1.414...e-05

  vc-call-backend                     5           0.043155      0.008631
vc-working-revision                 5           0.043155      0.008631
  <self or not profiled>              5           0.042453      0.0084906
  vc-file-getprop                     5           0.000702      0.0001404

  vc-default-registered               35          0.0005610000  1.602...e-05
  vc-find-backend-function            7           9.900...e-05  1.414...e-05
  vc-stay-local-p                     1           2e-05         2e-05
vc-make-backend-sym                 43          0.0006799999  1.581...e-05
  <self or not profiled>              43          0.0006799999  1.581...e-05

  vc-possible-master                  17          0.000388      2.282...e-05
vc-sccs-search-project-dir          17          0.000388      2.282...e-05
  <self or not profiled>              17          0.000388      2.282...e-05

  vc-call-backend                     16          9.199...e-05  5.749...e-06
vc-kill-buffer-hook                 17          9.799...e-05  5.764...e-06
  <self or not profiled>              17          9.799...e-05  5.764...e-06

Re: Hideously slow VC status queries fixed

[Eric S. Raymond]

Tom Tromey <tromey@redhat.com>:
> The vc-registered -> vc-call-backend edge seems particularly bad.
> But perhaps I'm misreading this, or we knew it, or this profiler is
> giving erroneous results.

Nope, there are structural reasons to think that's a likely hotspot.
I'll see what I can do about eliminating some of those calls.

> BTW, today's VC changes roughly halved the number of calls to
> vc-call-backend, but (according to oelp) the elapsed time hasn't
> changed much.  New profile appended.

Dang, I was hoping for more gain than that.  VC-Dired does seem
visibly snappier though.
-- 
		<a href="http://www.catb.org/~esr/">Eric S. Raymond</a>

Re: Hideously slow VC status queries fixed

[Richard Stallman]

    After a few minutes I got this:

	Warning (undo): Buffer `gcc' undo info was 3023389 bytes long.
	The undo info was discarded because it exceeded `undo-outer-limit'.

This probably means there is some buffer or some operation in which 
undo should be turned off entirely.  For instance, when vc-dired
fills the buffer with information, it may as well have undo turned
off during that.

Re: Hideously slow VC status queries fixed

[Eric S. Raymond]

Richard Stallman <rms@gnu.org>:
>     After a few minutes I got this:
> 
> 	Warning (undo): Buffer `gcc' undo info was 3023389 bytes long.
> 	The undo info was discarded because it exceeded `undo-outer-limit'.
> 
> This probably means there is some buffer or some operation in which 
> undo should be turned off entirely.  For instance, when vc-dired
> fills the buffer with information, it may as well have undo turned
> off during that.

Excellent point.  I went and did it.

vc-state and vc-dir-state have been the main performance
bottlenecks in this code from day one.  Time spent tuning them
is not wasted.
-- 
		<a href="http://www.catb.org/~esr/">Eric S. Raymond</a>

Re: Hideously slow VC status queries fixed

[Tom Tromey]

>>>>> "Eric" == Eric S Raymond <esr@thyrsus.com> writes:

>> Warning (undo): Buffer `gcc' undo info was 3023389 bytes long.
>> The undo info was discarded because it exceeded `undo-outer-limit'.

Eric> Excellent point.  I went and did it.

I don't think this change has any effect -- AIUI, with-temp-buffer
disables undo in the new buffer by default.

Also, the message mentions the 'gcc' buffer -- I think this is the
vc-dired buffer itself, not the temporary buffer made for the output
of 'svn status'.

I'm not really sure where to disable undo for this... maybe somewhere
in dired.

Tom

Re: Hideously slow VC status queries fixed

[Tom Tromey]

>>>>> "Tom" == Tom Tromey <tromey@redhat.com> writes:

Tom> I'm not really sure where to disable undo for this... maybe
Tom> somewhere in dired.

This patch seems to fix the undo problem.  I don't get a message any
more.  It doesn't appear to speed up vc-dired, though.

Tom

ChangeLog:
2007-12-28  Tom Tromey  <tromey@redhat.com>

	* vc.el (vc-dired-hook): Disable undo.

Index: vc.el
===================================================================
RCS file: /sources/emacs/emacs/lisp/vc.el,v
retrieving revision 1.501
diff -u -r1.501 vc.el
--- vc.el	28 Dec 2007 18:16:55 -0000	1.501
+++ vc.el	28 Dec 2007 20:04:59 -0000
@@ -2349,7 +2349,10 @@
     (if (and (vc-call-backend backend 'responsible-p default-directory)
 	     (vc-find-backend-function backend 'dir-state))
 	(vc-call-backend backend 'dir-state default-directory)))
-  (let (filename (inhibit-read-only t))
+  (let (filename
+	(inhibit-read-only t)
+	;; Temporarily disable undo.
+	(buffer-undo-list t))
     (goto-char (point-min))
     (while (not (eobp))
       (cond

Re: Hideously slow VC status queries fixed

[Dan Nicolaescu]

"Eric S. Raymond" <esr@snark.thyrsus.com> writes:

  > It gives me great pleasure to be able to announce that I have found,
  > and fixed, the bug that made C-x v d so godawful much slower than the
  > underlying commands.

Thank you so much for doing this!

There's still one source of inefficiency: files that are not vc-registered
at all. For example object files in a build tree. 

Try this: 

cd emacs/lisp/term   (because it is a small subdir)

for FF in `seq 1 1000`; do touch obj${FF}.o; done

(just create 1000 .o files)

emacs -q
M-x elp-instrument-package RET vc RET
C-x v d emacs/lisp/term RET
M-x elp-results RET

That will show  1000 calls to vc-bzr-registered, vc-git-registered,
vc-arch-registered, vc-svn-registered etc etc.

Another issue with vc-dired is that it does not show files that are not
registered and not ignored. So one cannot select the non-registered
files and register them in one shot...

Re: Hideously slow VC status queries fixed

[Alexandru Harsanyi]

On 27 Dec 2007, at 11:41 AM, Dan Nicolaescu wrote:

> "Eric S. Raymond" <esr@snark.thyrsus.com> writes:
>
>> It gives me great pleasure to be able to announce that I have found,
>> and fixed, the bug that made C-x v d so godawful much slower than the
>> underlying commands.
>
> Thank you so much for doing this!
>
> There's still one source of inefficiency: files that are not vc- 
> registered
> at all. For example object files in a build tree.
>
> Try this:
>
> cd emacs/lisp/term   (because it is a small subdir)
>
> for FF in `seq 1 1000`; do touch obj${FF}.o; done
>
> (just create 1000 .o files)
>
> emacs -q
> M-x elp-instrument-package RET vc RET
> C-x v d emacs/lisp/term RET
> M-x elp-results RET
>
> That will show  1000 calls to vc-bzr-registered, vc-git-registered,
> vc-arch-registered, vc-svn-registered etc etc.

One way to reduce the number of calls is to use the `vc-BACKEND- 
responsible-p' functions to determine which backends are responsible  
for files in a directory.  It will than only call the `vc-BACKEND- 
registered' function for the responsible backends only.

The speed of the vc-BACKEND-registered call be improved by having the  
`vc-BACKEND-dir-state' function set a property meaning 'not- 
registered' for every file that is not registered with that BACKEND.   
vc-BACKEND-registered will than check for that property before  
invoking the BACKEND command.

Best Regards,
Alex.

Re: Hideously slow VC status queries fixed

[Eric S. Raymond]

Dan Nicolaescu <dann@ics.uci.edu>:
> That will show  1000 calls to vc-bzr-registered, vc-git-registered,
> vc-arch-registered, vc-svn-registered etc etc.

That could be sped up by noticing which files would normally be excluded
by dired and using using that information to set an 'excluded 
property value.  If dir-state did that, all those calls would be avoided 

> Another issue with vc-dired is that it does not show files that are not
> registered and not ignored. So one cannot select the non-registered
> files and register them in one shot...

Yes, this has annoyed me.  Yes another reason to think about rewriting
vc-state and substantially enriching the repertoire of states it can
pass back.
-- 
		<a href="http://www.catb.org/~esr/">Eric S. Raymond</a>

Re: Hideously slow VC status queries fixed

[Stefan Monnier]

>> That will show  1000 calls to vc-bzr-registered, vc-git-registered,
>> vc-arch-registered, vc-svn-registered etc etc.

> That could be sped up by noticing which files would normally be excluded
> by dired and using using that information to set an 'excluded 
> property value.  If dir-state did that, all those calls would be avoided 

Doesn't sound right: under PCL-CVS for example I don't need any such
hack.  I just look at CVS's `update' output and immediately see which
files are "not ignored and not registered".  Many/most backends do that
as well.

So we should add a vc-state "need-register" or somesuch.


        Stefan

Re: Hideously slow VC status queries fixed

[Stefan Monnier]

> People who wrote backends for later VCSes followed suit, so focused
> on getting their backends minimally working that they failed to notice
> that the upper-level logic was perversely misdesigned.

If you read some of the comments in the code or in the relevant
mailing-lists, you'll soon discover that nobody failed to notice
the misdesign.
Thanks for working on fixing it.


        Stefan