Emacs 23.0 is much slower starting than Emacs 22.3

Emacs 23.0 is much slower starting than Emacs 22.3

[Alan Mackenzie]

Hi, Emacs,

I have an extremely medium speed processor (Athlon 1.2 GHz) and, at the
moment, a well-padded .emacs.desktop.

Starting Emacs 22.3 takes 23 seconds.
Starting Emacs 23.0 takes 38 seconds.

Emacs 23 thus starts up at about three fifths the speed of 22.  This is
very noticeable, and not a good thing.

I haven't tried to tie down why this is.

-- 
Alan Mackenzie (Nuremberg, Germany).

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Stefan Monnier]

> I have an extremely medium speed processor (Athlon 1.2 GHz) and, at the
> moment, a well-padded .emacs.desktop.

> Starting Emacs 22.3 takes 23 seconds.
> Starting Emacs 23.0 takes 38 seconds.

> Emacs 23 thus starts up at about three fifths the speed of 22.  This is
> very noticeable, and not a good thing.

> I haven't tried to tie down why this is.

Could it be due to the extra font-selection efforts?
You could compare the GUI vs text modes, to get a first
impression of where the time difference goes.


        Stefan

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[John covici]

I have noticed this as well using text mode.  It seems particularly
slow loading my desktop (106 buffers).  Also, sending mail is slower
-- looks like lisp processing is just slower.

on Wednesday 10/22/2008 Stefan Monnier(monnier@iro.umontreal.ca) wrote
 > > I have an extremely medium speed processor (Athlon 1.2 GHz) and, at the
 > > moment, a well-padded .emacs.desktop.
 > 
 > > Starting Emacs 22.3 takes 23 seconds.
 > > Starting Emacs 23.0 takes 38 seconds.
 > 
 > > Emacs 23 thus starts up at about three fifths the speed of 22.  This is
 > > very noticeable, and not a good thing.
 > 
 > > I haven't tried to tie down why this is.
 > 
 > Could it be due to the extra font-selection efforts?
 > You could compare the GUI vs text modes, to get a first
 > impression of where the time difference goes.
 > 
 > 
 >         Stefan
 > 

-- 
Your life is like a penny.  You're going to lose it.  The question is:
How do
you spend it?

         John Covici
         covici@ccs.covici.com

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Alan Mackenzie]

Hi, Stefan!

On Wed, Oct 22, 2008 at 09:23:34AM -0400, Stefan Monnier wrote:
> > I have an extremely medium speed processor (Athlon 1.2 GHz) and, at
> > the moment, a well-padded .emacs.desktop.

> > Starting Emacs 22.3 takes 23 seconds.
> > Starting Emacs 23.0 takes 38 seconds.

> > Emacs 23 thus starts up at about three fifths the speed of 22.  This
> > is very noticeable, and not a good thing.

> > I haven't tried to tie down why this is.

> Could it be due to the extra font-selection efforts?
> You could compare the GUI vs text modes, to get a first
> impression of where the time difference goes.

The above times were on tty's.  Trying it on X-Windows, there was no
difference (or, at most, 1 or 2 seconds longer).

>         Stefan

-- 
Alan Mackenzie (Nuremberg, Germany).

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[David De La Harpe Golden]

Alan Mackenzie wrote:

>>> I have an extremely medium speed processor (Athlon 1.2 GHz) and, at
>>> the moment, a well-padded .emacs.desktop.
> 
>>> Starting Emacs 22.3 takes 23 seconds.
>>> Starting Emacs 23.0 takes 38 seconds.
> 

> The above times were on tty's.  Trying it on X-Windows, there was no
> difference (or, at most, 1 or 2 seconds longer).
> 
>>         Stefan
> 

FWIW, I'd find your emacs22 time pretty unacceptable, never mind the 
emacs23 one, even on a 1.2GHz-class machine. Are a lot of people
putting up with that sort of start time? Ouch.

Of course it could be an emacs bug triggered on your system and not 
mine, but I kinda wonder: is it only emacs or is everything slow? Is it 
only slow to start or slow to update the display and whatnot?  Makes me 
think you might have a local system issue causing an I/O bottleneck, is 
all, maybe no DMA on your HDD, or your system's low on RAM and is 
already swapping or something.

On my admittedly higher-end newish multicore (but each core is only ~ 
2GHz and emacs isn't parallelized...) gnu+linux system, emacs23 takes 1 
to 2 seconds to start, including the ridiculous happy-dance across the 
screen the initial X11 frame does (known-bug afaik), and I thought it 
was getting a bit sluggish (whenever an app start time is > 1 sec I 
start to notice and get irritated), but I put it down to the 
happy-dancing.   With a .emacs.desktop of 100 random .el files from the 
emacs source tree, start time was 2 to 3 seconds.

Iceweasel takes 2 to 3 secs and oowriter (probably the bloatiest thing I 
have installed)  11 secs ?

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Eli Zaretskii]

> Date: Wed, 22 Oct 2008 09:11:36 +0000
> From: Alan Mackenzie <acm@muc.de>
> 
> I have an extremely medium speed processor (Athlon 1.2 GHz) and, at the
> moment, a well-padded .emacs.desktop.
> 
> Starting Emacs 22.3 takes 23 seconds.
> Starting Emacs 23.0 takes 38 seconds.

Is this with -Q?  If not, what are numbers with -Q?

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Richard M. Stallman]

    Emacs 23 thus starts up at about three fifths the speed of 22.  This is
    very noticeable, and not a good thing.

How about putting code to record the current time
at a few places in startup.el, in both versions?
That way you can maybe find out which parts of the code
have got slower.

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Alan Mackenzie]

Hi, David!

On Wed, Oct 22, 2008 at 05:46:51PM +0100, David De La Harpe Golden wrote:
> Alan Mackenzie wrote:

> >>>I have an extremely medium speed processor (Athlon 1.2 GHz) and, at
> >>>the moment, a well-padded .emacs.desktop.

> >>>Starting Emacs 22.3 takes 23 seconds.
> >>>Starting Emacs 23.0 takes 38 seconds.


> >The above times were on tty's.  Trying it on X-Windows, there was no
> >difference (or, at most, 1 or 2 seconds longer).

> >>        Stefan


> FWIW, I'd find your emacs22 time pretty unacceptable, never mind the
> emacs23 one, even on a 1.2GHz-class machine. Are a lot of people
> putting up with that sort of start time? Ouch.

Hey, don't be so hard on my poor little PC!  It's getting on a bit[*].
There's 83 files being loaded by desktop, with a total of 7801019 bytes.

emacs-22 -Q starts in ~0.4 seconds.
emacs-23 -Q starts in ~0.7 seconds.

[*] For non-native English speakers: "he's getting on a bit" is a
euphemism for "he's too old (for something)".

> Of course it could be an emacs bug triggered on your system and not
> mine, but I kinda wonder: is it only emacs or is everything slow? Is it
> only slow to start or slow to update the display and whatnot?  Makes me
> think you might have a local system issue causing an I/O bottleneck, is
> all, maybe no DMA on your HDD, or your system's low on RAM and is
> already swapping or something.

It's a 7 year old PC, with a 7 yo HDD, but with plenty of RAM (768 Mb).
You really think 23 seconds is slow, loading emacs + 83 files?

> On my admittedly higher-end newish multicore (but each core is only ~ 
> 2GHz and emacs isn't parallelized...) gnu+linux system, emacs23 takes 1 
> to 2 seconds to start, .....

How many file does your desktop load, and what's their total size?

> , ..... including the ridiculous happy-dance across the screen the
> initial X11 frame does (known-bug afaik), and I thought it was getting
> a bit sluggish (whenever an app start time is > 1 sec I start to notice
> and get irritated), but I put it down to the happy-dancing.   With a
> .emacs.desktop of 100 random .el files from the emacs source tree,
> start time was 2 to 3 seconds.

OK, 100 random files.el.  How big were they?

> Iceweasel takes 2 to 3 secs and oowriter (probably the bloatiest thing I 
> have installed)  11 secs ?

Firefox 1.0.4 takes ~2.5 secs to load (but it was probably in the disk
cache when I timed it).

-- 
Alan Mackenzie (Nuremberg, Germany).

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Eli Zaretskii]

> Date: Wed, 22 Oct 2008 21:12:02 +0000
> From: Alan Mackenzie <acm@muc.de>
> Cc: Stefan Monnier <monnier@iro.umontreal.ca>, emacs-devel@gnu.org
> 
> > >>>Starting Emacs 22.3 takes 23 seconds.
> > >>>Starting Emacs 23.0 takes 38 seconds.

Is this with cold or warm cache?  Is there a difference?

> > FWIW, I'd find your emacs22 time pretty unacceptable, never mind the
> > emacs23 one, even on a 1.2GHz-class machine. Are a lot of people
> > putting up with that sort of start time? Ouch.
> 
> Hey, don't be so hard on my poor little PC!  It's getting on a bit[*].
> There's 83 files being loaded by desktop, with a total of 7801019 bytes.

How many seconds does it take to run "sed -n -e s/xyzzy/xyzzy/p" on
all those files, on that machine?  (That should give us a baseline of
the disk and filesystem performance.)

> emacs-22 -Q starts in ~0.4 seconds.
> emacs-23 -Q starts in ~0.7 seconds.

Can you see if some files your desktop visits take much longer than
others?

How about loading elp.el early on and profiling the startup phase on
both versions?

On GNU/Linux, FreeBSD, and MS-Windows, you can also profile Emacs on
the C level, search for PROFILING in emacs.c.

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Alan Mackenzie]

Hi, Eli!

On Wed, Oct 22, 2008 at 08:26:28PM +0200, Eli Zaretskii wrote:
> > Date: Wed, 22 Oct 2008 09:11:36 +0000
> > From: Alan Mackenzie <acm@muc.de>

> > I have an extremely medium speed processor (Athlon 1.2 GHz) and, at the
> > moment, a well-padded .emacs.desktop.

> > Starting Emacs 22.3 takes 23 seconds.
> > Starting Emacs 23.0 takes 38 seconds.

> Is this with -Q?  If not, what are numbers with -Q?

With -Q:
Emacs 22: ~0.4s
Emacs 23: ~0.7s

Even here, Emacs 23 is noticeably slower.

With a one-line .emacs, (desktop-save-mode 1), and starting with
--no-site-file, the timing for Emacs 22 was essentially the same (~28s,
but I was a bit slow typing 'y' to ~5 prompts for File local variables
and hi-lock-mode's fonts).

Emacs 23 threw an error after loading ~15 files.  The error was
"c-define-lang-constant: `c-lang-defconst' must be used in a file", which
is one of mine.  :-(  But the loading of the files seemed just as
sluggish.

It doesn't seem like it's anything in my .emacs/site-start.el causing the
slowness.

-- 
Alan Mackenzie (Nuremberg, Germany).

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Eli Zaretskii]

> Date: Wed, 22 Oct 2008 21:40:53 +0000
> Cc: emacs-devel@gnu.org
> From: Alan Mackenzie <acm@muc.de>
> 
> With -Q:
> Emacs 22: ~0.4s
> Emacs 23: ~0.7s
> 
> Even here, Emacs 23 is noticeably slower.

Only if you assume that the slowdown is multiplicative.  But we have
no evidence yet that this is the case.  In absolute numbers, 0.3 sec
is a negligibly small slow-down.

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Miles Bader]

David De La Harpe Golden <david@harpegolden.net> writes:
> FWIW, I'd find your emacs22 time pretty unacceptable, never mind the
> emacs23 one, even on a 1.2GHz-class machine. Are a lot of people
...
> On my admittedly higher-end newish multicore (but each core is only ~
> 2GHz and emacs isn't parallelized...) gnu+linux system, emacs23 takes 1
> to 2 seconds to start

Note that he was including the time to load his "well-padded desktop",
and in my experience this greatly increases startup time.

Obviously it would be nice to see a more precise definition of what
exactly is being measured...

-Miles

-- 
`Suppose Korea goes to the World Cup final against Japan and wins,' Moon said.
`All the past could be forgiven.'   [NYT]

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[David De La Harpe Golden]

Alan Mackenzie wrote:

> 
> OK, 100 random files.el.  How big were they?
> 

Probably fairly small. I went back and did the 180 .c files from the 
emacs source tree, totalling 9.2MB, and that took 6-7 secs (Which was a 
bit slower than I expected!)

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Alan Mackenzie]

Hi, Miles,

On Thu, Oct 23, 2008 at 10:29:45AM +0900, Miles Bader wrote:
> David De La Harpe Golden <david@harpegolden.net> writes:
> > FWIW, I'd find your emacs22 time pretty unacceptable, never mind the
> > emacs23 one, even on a 1.2GHz-class machine. Are a lot of people
> ...
> > On my admittedly higher-end newish multicore (but each core is only ~
> > 2GHz and emacs isn't parallelized...) gnu+linux system, emacs23 takes 1
> > to 2 seconds to start

> Note that he was including the time to load his "well-padded desktop",
> and in my experience this greatly increases startup time.

> Obviously it would be nice to see a more precise definition of what
> exactly is being measured...

Fair enough.  Here's a copy of my C-x C-b immediately after starting
Emacs:

.   debian.README       162755  Text              ~/debian.README
 %  *info*<2>           299364  Info              (elisp)Version Info
    desktop.el           49601  Emacs-Lisp        ~/emacs/emacs/lisp/desktop.el
    .emacs               40647  Emacs-Lisp        ~/.emacs
    emacs.README        180026  Text              ~/emacs.README
    regression_in_emacs.: 7280  Text              ~/regression_in_emacs.txt
    silly.txt               13  Text              ~/silly.txt
    simple.el           250115  Emacs-Lisp        ~/emacs/emacs/lisp/simple.el
    ChangeLog<2>        546098  Change Log        ~/emacs/emacs/lisp/ChangeLog
 %  ielm.el.gz           22075  Emacs-Lisp        /usr/local/share/emacs/22.3/lisp/ielm.el.gz
 %  simple.el~          249554  Emacs-Lisp        ~/emacs/emacs/lisp/simple.el~
 %  simple.el.gz        222164  Emacs-Lisp        /usr/local/share/emacs/22.3/lisp/simple.el.gz
    cc-mode.acm        1038609  Text              ~/cc-mode-5.31/cc-mode.acm
    undo.c               22165  C/l               ~/emacs/emacs/src/undo.c
    icicles.el           41928  Emacs-Lisp        ~/icicles/icicles.el
    ChangeLog           568800  Change Log        ~/emacs/emacs/src/ChangeLog
    cc-mode.el           62702  Emacs-Lisp        ~/cc-mode-5.31.n/cc-mode.el
    king-bishop.el        3684  Emacs-Lisp        ~/king-bishop.el
    site-start.el        13092  Emacs-Lisp        /usr/local/share/emacs/site-lisp/site-start.el
    colascione.c             5  C/l               ~/colascione.c
    insdel.c             68847  C/l               /usr/src/emacs-22.3/src/insdel.c
    test.c                7426  C/l               ~/mkcfg/test.c
    cc-cmds.201008.el.: 323961  Fundamental       ~/cc-mode-5.31.n/cc-cmds.201008.el.annotate
    cc-cmds.el          160568  Emacs-Lisp        ~/cc-mode-5.31.n/cc-cmds.el
 %  *info*<4>           299949  Info              (cvs)annotate options
    editfns.c           141738  C/l               /usr/src/emacs-22.3/src/editfns.c
    asdf.txt              3814  Text              ~/asdf.txt
    cc-styles.el         23875  Emacs-Lisp        ~/cc-mode-5.31.n/cc-styles.el
    asdf                    62  Fundamental       ~/asdf
    cc-engine.el        353245  Emacs-Lisp        ~/cc-mode-5.31.n/cc-engine.el
    000tests.el          41417  Emacs-Lisp        ~/cc-mode-5.31.n/tests/000tests.el
    rauhamaa.java        11303  Java/l            ~/rauhamaa.java
    cc-langs.el         123362  Emacs-Lisp        ~/cc-mode-5.31.n/cc-langs.el
 %  cc-langs.191008.el.di: 941  Diff              ~/cc-mode-5.31.n/cc-langs.191008.el.diff
 %  *info*<3>           271710  Info              (emacs)Key Index
 %  manual.txt.gz       294781  Text              /usr/share/doc/mutt/manual.txt.gz
    szmek.java            5309  Java/l            ~/szmek.java
    bugtracker            6381  Outline           ~/emacs/emacs/admin/notes/bugtracker
    typein.c               539  C/l               ~/typein.c
    spaknik.c             4992  C/l               ~/spaknik.c
    demolition-of-shell.: 3094  Text              ~/demolition-of-shell.txt
 %  nicolaescu.c          1157  Diff              ~/nicolaescu.c
    ciolfi.c              1555  C/l               ~/ciolfi.c
    cc-defs.el           78928  Emacs-Lisp        ~/cc-mode-5.31.n/cc-defs.el
    cc-vars.el           70779  Emacs-Lisp        ~/cc-mode-5.31.n/cc-vars.el
    test-comment-in-macro: 286  C/l               ~/test-comment-in-macro.c
 %  *info*<5>          1114311  Info              (gcc-3.3)Option Summary
    hausordnung.txt       6976  Text              ~/hausordnung.txt
    marshall7.cpp         1537  C++/l             ~/marshall7.cpp
    marshalla.cpp         1861  C++/l             ~/marshalla.cpp
    marshall9.cpp         2311  C++/l             ~/marshall9.cpp
    cc-fonts.el          87831  Emacs-Lisp        ~/cc-mode-5.31.n/cc-fonts.el
    templates-6.cc         544  C++/l             ~/cc-mode-5.31.n/tests/templates-6.cc
    yu.cc                  162  C++/l             ~/yu.cc
    forehand.cc           1243  C++/l             ~/forehand.cc
    pp-regexp.el          2494  Emacs-Lisp        ~/pp-regexp.el
    cc-bytecomp.el       16241  Emacs-Lisp        ~/cc-mode-5.31.n/cc-bytecomp.el
    README                4657  Fundamental       ~/cc-mode-5.31.n/README
    nontemplate-exprs-1.f:  66  Fundamental       ~/cc-mode-5.31.n/tests/nontemplate-exprs-1.face
    test.c++              5951  C++/l             ~/mkcfg/test.c++
    cc-mode.texi        260035  Texinfo           ~/cc-mode-5.31.n/cc-mode.texi
    cc-align.el          46324  Emacs-Lisp        ~/cc-mode-5.31.n/cc-align.el
    cc-awk.el            51144  Emacs-Lisp        ~/cc-mode-5.31.n/cc-awk.el
    .bashrc               4577  Shell-script[bas  ~/.bashrc
    canonic-key-sequence: 4168  Emacs-Lisp        ~/canonic-key-sequence.el
    ghc-6.8.3              208  Shell-script[sh]  ~/ghc-6.8.3
    sullivan.c             199  C/l               ~/sullivan.c
    update_trunk.sh       6255  Shell-script[bas  ~/cc-mode-5.31.n/update_trunk.sh
    c-syntax-ppss.el      1411  Emacs-Lisp        ~/c-syntax-ppss.el
 %  objc-enhance_v6a.pat: 5458  Diff              ~/cc-mode-5.31.n/cc-mode-5.31.n.robert6/objc-enhance_v6a.patch
    uniquify_log.awk      4947  AWK/l             ~/uniquify_log.awk
    todo.txt             44492  Text              ~/todo.txt
    FGM_Lebenslauf_2007-: 8431  Text              ~/FGM_Lebenslauf_2007-12-16.txt
    Adrian-Roberts.25050: 6440  Text              ~/Adrian-Roberts.250508.txt
    jobs.acm              8406  Text              ~/jobs.acm
    testObjCmethodCallAli: 413  ObjC/l            ~/cc-mode-5.31.n/cc-mode-5.31.n.robert/testObjCmethodCallAlign.m
    TODO.txt              1628  Text              ~/TODO.txt
    sullivan.el           1011  Emacs-Lisp        ~/sullivan.el
    test-marshalla.cpp     182  C++/l             ~/test-marshalla.cpp
    test.awk              3057  AWK/l             ~/mkcfg/test.awk
    cc-menus.el          15352  Emacs-Lisp        ~/cc-mode-5.31.n/cc-menus.el
    *scratch*                0  Lisp Interaction
  * *Messages*            3467  Fundamental

TOTALS 81 files; 7801019 bytes.

This is not intended to be an intellectual puzzle to work out what I'm
working on.  :-)

> -Miles

-- 
Alan Mackenzie (Nuremberg, Germany).

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Alan Mackenzie]

Hi, David!

On Thu, Oct 23, 2008 at 07:53:14AM +0100, David De La Harpe Golden wrote:
> Alan Mackenzie wrote:

> >
> >OK, 100 random files.el.  How big were they?
> >

> Probably fairly small. I went back and did the 180 .c files from the 
> emacs source tree, totalling 9.2MB, and that took 6-7 secs (Which was a 
> bit slower than I expected!)

OK.  Was that Emacs 22 or 23?  Presumably 23.  Any chance you could time
it using the other Emacs?

-- 
Alan Mackenzie (Nuremberg, Germany).

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Alan Mackenzie]

Hi, Eli!

On Wed, Oct 22, 2008 at 11:19:56PM +0200, Eli Zaretskii wrote:
> > Date: Wed, 22 Oct 2008 21:12:02 +0000
> > From: Alan Mackenzie <acm@muc.de>
> > Cc: Stefan Monnier <monnier@iro.umontreal.ca>, emacs-devel@gnu.org

> > > >>>Starting Emacs 22.3 takes 23 seconds.
> > > >>>Starting Emacs 23.0 takes 38 seconds.

> Is this with cold or warm cache?  Is there a difference?

A warm start each time.

> > > FWIW, I'd find your emacs22 time pretty unacceptable, never mind
> > > the emacs23 one, even on a 1.2GHz-class machine. Are a lot of
> > > people putting up with that sort of start time? Ouch.

> > Hey, don't be so hard on my poor little PC!  It's getting on a
> > bit[*].  There's 83 files being loaded by desktop, with a total of
> > 7801019 bytes.

> How many seconds does it take to run "sed -n -e s/xyzzy/xyzzy/p" on
> all those files, on that machine?  (That should give us a baseline of
> the disk and filesystem performance.)

From a cold start, "time grep wtioxxhs $BUFFERS" gave
real    0m1.798s
user    0m0.015s
sys     0m0.034s

Second time round, with the files presumably in the file cache:
real    0m0.034s
user    0m0.012s
sys     0m0.020s

So I don't think my PC's disk drives are the cause.

[ .... ]

-- 
Alan Mackenzie (Nuremberg, Germany).

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[David De La Harpe Golden]

Alan Mackenzie wrote:
> Hi, David!
> 
> On Thu, Oct 23, 2008 at 07:53:14AM +0100, David De La Harpe Golden wrote:
>> Alan Mackenzie wrote:
> 
>>> OK, 100 random files.el.  How big were they?
>>>
> 
>> Probably fairly small. I went back and did the 180 .c files from the 
>> emacs source tree, totalling 9.2MB, and that took 6-7 secs (Which was a 
>> bit slower than I expected!)
> 
> OK.  Was that Emacs 22 or 23?  Presumably 23.  Any chance you could time
> it using the other Emacs?
> 

Yes, now using "time emacs -f kill-emacs"  (warm cache this time, not
rebooting between runs...)

emacs	run	real	user	sys
22 	1	4.880	3.960	0.180
22	2	4.589	3.992	0.136
22	3	4.764	4.076	0.176
23	4	7.275	6.636	0.120
23	5	6.958	6.276	0.188
23	6	6.898	6.268	0.132

So yeah, 23 is slower.

I tried just putting 180 find-file-noselects in a file and loading it
i.e.

$ find /usr/local/src/emacs -name '*.c' -printf \
     '(find-file-noselect "%p")\n' >fftest.el
$ emacs --batch --eval '(byte-compile-file "fftest.el")'
$ time emacs -l fftest.elc -f kill-emacs

emacs	run	real	user	sys
22	1	4.523	3.888	0.136
22	2	4.744	4.172	0.112
22	3	4.457	3.836	0.176
23	4	7.177	6.532	0.152
23	5	7.198	6.544	0.160
23	6	7.159	6.472	0.220


So FWIW probably the problem is in the find-file call path rather than 
anything desktop.el is doing in particular (though there IS a kinda 
dubious mapc in desktop-create-buffer, but it likely doesn't really bite 
until rather larger file counts again (triangular progression in file 
count)).

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Eli Zaretskii]

> Date: Thu, 23 Oct 2008 17:57:29 +0100
> From: David De La Harpe Golden <david@harpegolden.net>
> Cc: Stefan Monnier <monnier@iro.umontreal.ca>, emacs-devel@gnu.org
> 
> I tried just putting 180 find-file-noselects in a file and loading it
> i.e.
> 
> $ find /usr/local/src/emacs -name '*.c' -printf \
>      '(find-file-noselect "%p")\n' >fftest.el
> $ emacs --batch --eval '(byte-compile-file "fftest.el")'
> $ time emacs -l fftest.elc -f kill-emacs
> 
> emacs	run	real	user	sys
> 22	1	4.523	3.888	0.136
> 22	2	4.744	4.172	0.112
> 22	3	4.457	3.836	0.176
> 23	4	7.177	6.532	0.152
> 23	5	7.198	6.544	0.160
> 23	6	7.159	6.472	0.220
> 
> 
> So FWIW probably the problem is in the find-file call path rather than 
> anything desktop.el is doing in particular

Sounds plausible.  Next question: is the slow-down connected in any
way with decoding the buffer?  To see if this is a factor, you could
compare 180 calls to insert-file-contents with the same number of
calls to insert-file-contents-literally, in both Emacs 22 and 23.

TIA

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Eli Zaretskii]

> Date: Thu, 23 Oct 2008 09:21:32 +0000
> Cc: emacs-devel@gnu.org, monnier@iro.umontreal.ca, david@harpegolden.net
> From: Alan Mackenzie <acm@muc.de>
> 
> > How many seconds does it take to run "sed -n -e s/xyzzy/xyzzy/p" on
> > all those files, on that machine?  (That should give us a baseline of
> > the disk and filesystem performance.)
> 
> >From a cold start, "time grep wtioxxhs $BUFFERS" gave
> real    0m1.798s
> user    0m0.015s
> sys     0m0.034s
> 
> Second time round, with the files presumably in the file cache:
> real    0m0.034s
> user    0m0.012s
> sys     0m0.020s
> 
> So I don't think my PC's disk drives are the cause.

Right, looks like neither the disk nor the filesystem are the factor.

So we need to find which Emacs primitives became slower in v23.

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Lennart Borgman]

On Thu, Oct 23, 2008 at 11:52 PM, Eli Zaretskii <eliz@gnu.org> wrote:
>> Date: Thu, 23 Oct 2008 17:57:29 +0100
>> From: David De La Harpe Golden <david@harpegolden.net>
>> Cc: Stefan Monnier <monnier@iro.umontreal.ca>, emacs-devel@gnu.org
>>
>> I tried just putting 180 find-file-noselects in a file and loading it
>> i.e.
>>
>> $ find /usr/local/src/emacs -name '*.c' -printf \
>>      '(find-file-noselect "%p")\n' >fftest.el
>> $ emacs --batch --eval '(byte-compile-file "fftest.el")'
>> $ time emacs -l fftest.elc -f kill-emacs
>>
>> emacs run     real    user    sys
>> 22    1       4.523   3.888   0.136
>> 22    2       4.744   4.172   0.112
>> 22    3       4.457   3.836   0.176
>> 23    4       7.177   6.532   0.152
>> 23    5       7.198   6.544   0.160
>> 23    6       7.159   6.472   0.220
>>
>>
>> So FWIW probably the problem is in the find-file call path rather than
>> anything desktop.el is doing in particular
>
> Sounds plausible.  Next question: is the slow-down connected in any
> way with decoding the buffer?  To see if this is a factor, you could
> compare 180 calls to insert-file-contents with the same number of
> calls to insert-file-contents-literally, in both Emacs 22 and 23.

I did a fast test using something as simple as this:


(defun test-insert-dir (dir literally)
  (let ((files (directory-files dir t)))
    (dolist (file files)
      (unless (file-directory-p file)
        (with-temp-buffer
          (if literally
              (insert-file-contents-literally file)
            (insert-file-contents file)))))))

(defun test-insert-emacs-lisp-dir ()
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" nil))
  (message "======================= After cache warm up")
  (message "Timing insert-file-contents-literally:")
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" t))
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" t))
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" t))
  (message "Timing insert-file-contents:")
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" nil))
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" nil))
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" nil))
  (message "Ready"))

The output was

  ======================= After cache warm up
  Timing insert-file-contents-literally:
  Elapsed time: 5.531000s (0.094000s in 1 GCs)
  Elapsed time: 5.594000s
  Elapsed time: 5.828000s (0.093000s in 1 GCs)
  Timing insert-file-contents:
  Elapsed time: 9.484000s (0.188000s in 2 GCs)
  Elapsed time: 8.922000s (0.188000s in 2 GCs)
  Elapsed time: 8.953000s (0.203000s in 2 GCs)

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[David De La Harpe Golden]

Eli Zaretskii wrote:


>> So FWIW probably the problem is in the find-file call path rather than 
>> anything desktop.el is doing in particular
> 
> Sounds plausible.  Next question: is the slow-down connected in any
> way with decoding the buffer?  To see if this is a factor, you could
> compare 180 calls to insert-file-contents with the same number of
> calls to insert-file-contents-literally, in both Emacs 22 and 23.
> 
> TIA

Haven't got to that that - however, insert-file-contents may only 
account for < 10% of the total time spent in find-file-noselect-1, at 
least according to the elp profiler. Though it may not work right at all 
on C functions? (note doubled call count) - However, I then wrapped the 
insert-file-contents call in find-file-noselect-1 in an elisp helper 
function (find-file-noselect-1-h below) and got a quasi-consistent 
figure for it, see [1] below for results, suggesting it may really be 
that small?

[Aside: Also turns out upping gc-cons-threshold shaves 2 secs off that 7 
sec time for 180 files.  Just maybe opening a bunch of files one after 
the other causes the memory usage to grow rapidly, causing the gc to 
kick in... so that's one, though probably fairly necessary, slowdown]


[1] (n.b. this was without upped gc-cons-threshold)
Function Name			CallCt	    ElapsedTime	  AverageTime
find-file-noselect              180         5.4325150000  0.0301806388
find-file-noselect-1            180         4.4660830000  0.0248115722
insert-file-contents            361         0.3358580000  0.0009303545
find-file-noselect-1-h          180         0.3062349999  0.0017013055
make-local-variable             10477       0.0153409999  1.464...e-06
abbreviate-file-name            730         0.0095040000  1.301...e-05
kill-buffer                     185         0.0034050000  1.840...e-05
kill-local-variable             1084        0.0008220000  7.583...e-07
normal-backup-enable-predicate  180         0.0006289999  3.494...e-06
erase-buffer                    361         0.0003230000  8.947...e-07
set-buffer-multibyte            181         0.0001579999  8.729...e-07

[2[ gc-cons-threshold to 1G
find-file-noselect              180         3.2771109999  0.0182061722
find-file-noselect-1            180         2.5760030000  0.0143111277
insert-file-contents            361         0.3392750000  0.0009398199
find-file-noselect-1-h          180         0.3094899999  0.0017193888
make-local-variable             10477       0.0170539999  1.627...e-06
abbreviate-file-name            730         0.0157539999  2.158...e-05
kill-buffer                     185         0.0047130000  2.547...e-05
kill-local-variable             1084        0.0008650000  7.979...e-07
normal-backup-enable-predicate  180         0.0007309999  4.061...e-06
erase-buffer                    361         0.0003520000  9.750...e-07
set-buffer-multibyte            181         0.0001799999  9.944...e-07

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Lennart Borgman]

On Fri, Oct 24, 2008 at 12:47 AM, David De La Harpe Golden
<david@harpegolden.net> wrote:
> Eli Zaretskii wrote:
>
>
>>> So FWIW probably the problem is in the find-file call path rather than
>>> anything desktop.el is doing in particular
>>
>> Sounds plausible.  Next question: is the slow-down connected in any
>> way with decoding the buffer?  To see if this is a factor, you could
>> compare 180 calls to insert-file-contents with the same number of
>> calls to insert-file-contents-literally, in both Emacs 22 and 23.
>>
>> TIA
>
> Haven't got to that that - however, insert-file-contents may only account
> for < 10% of the total time spent in find-file-noselect-1, at least
> according to the elp profiler.

Based on that observation system calls other than reading the file
contents looks most suspicious to me. In `after-find-file' (which is
called at the end of `find-file-noselect-1') there are some calls to
`file-attributes'. Are they perhaps involved?

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Lennart Borgman]

On Fri, Oct 24, 2008 at 1:12 AM, Lennart Borgman
<lennart.borgman@gmail.com> wrote:
> In `after-find-file' (which is
> called at the end of `find-file-noselect-1') there are some calls to
> `file-attributes'. Are they perhaps involved?

There is also a call to `file-modes'. I did some further tests:

  Timing insert-file-contents-literally:
  Elapsed time: 8.375000s (0.187000s in 1 GCs)
  Timing insert-file-contents:
  Elapsed time: 14.297000s (0.312000s in 2 GCs)
  Timing file-attributes:
  Elapsed time: 5.890000s (0.156000s in 1 GCs)
  Timing file-exists-p:
  Elapsed time: 6.672000s (0.125000s in 1 GCs)
  Timing file-modes:
  Elapsed time: 5.609000s (0.188000s in 1 GCs)

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[David De La Harpe Golden]

Lennart Borgman wrote:


> Based on that observation system calls other than reading the file
> contents looks most suspicious to me. In `after-find-file' (which is
> called at the end of `find-file-noselect-1') there are some calls to
> `file-attributes'. Are they perhaps involved?

Bah, my bad, somehow missed that inside the if statement the first pass
through, duh..  Yes, it is mostly "after-find-file", but the call to 
"normal-mode" is the killer, not the file attributes calls in 
"after-find-file" itself! - [1]

"normal-mode" bulk is is split into "set-auto-mode" and 
"hack-local-variables" fairly evenly (roughly 11:9 as below)

Most of the latter is in "hack-project-variables", and most of /that/ is
"project-find-settings-file", and most of that is the 
"locate-dominating-file" walk.
+++ Wasn't the project functionality (.dir-settings.el variable 
settings) new in emacs23? That may well account for emacs22->emacs23 ?
For every file loaded, it's redoing that...

+++ Which leaves set-auto-mode...


[1]
find-file-noselect         180         3.3577020000  0.0186539000
find-file-noselect-1       180         2.6044840000  0.0144693555
after-find-file            180         2.2709340000  0.0126163000
normal-mode                180         2.0908219999  0.0116156777
set-auto-mode              180         1.141377      0.0063409833
hack-local-variables       180         0.9163369999  0.0050907611
hack-project-variables     180         0.8940040000  0.0049666888
project-find-settings-file 180         0.8922979999  0.0049572111
locate-dominating-file     180         0.890476      0.0049470888
insert-file-contents       361         0.3547089999  0.0009825734
run-hooks                  2406        0.2279640000  9.474...e-05
re-search-forward          1453        0.1557330000  0.0001071803
vc-find-file-hook          180         0.1458039999  0.0008100222
font-lock-mode             722         0.0745249999  0.0001032202
file-attributes            1476        0.0304240000  2.061...e-05
make-local-variable        10477       0.0182779999  1.744...e-06
file-name-nondirectory     7843        0.0176319999  2.248...e-06
abbreviate-file-name       730         0.0165959999  2.273...e-05
search-forward             1811        0.0137990000  7.619...e-06
file-exists-p              756         0.0132379999  1.751...e-05
fundamental-mode           180         0.012926      7.181...e-05
file-name-directory       4091        0.0107010000  2.615...e-06

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Lennart Borgman]

On Fri, Oct 24, 2008 at 2:13 AM, David De La Harpe Golden
<david@harpegolden.net> wrote:
> Lennart Borgman wrote:
>
>
>> Based on that observation system calls other than reading the file
>> contents looks most suspicious to me. In `after-find-file' (which is
>> called at the end of `find-file-noselect-1') there are some calls to
>> `file-attributes'. Are they perhaps involved?
>
> Bah, my bad, somehow missed that inside the if statement the first pass
> through, duh..  Yes, it is mostly "after-find-file", but the call to
> "normal-mode" is the killer, not the file attributes calls in
> "after-find-file" itself! - [1]

It is probably different on w32 then. It looks like `normal-mode'
takes maybe 1.5 time insert+file-attr+file-modes+file-exist on w32.
(But I did not use elp, maybe I missed something.)

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[David De La Harpe Golden]

David De La Harpe Golden wrote:


> +++ Which leaves set-auto-mode...

Which seems to be mostly the particular mode - So of course, this can 
presumably vary wildly from mode to mode, but let's take c-mode (seeing 
as it's for the c files I was testing with):

set-auto-mode->set-auto-mode-0->
c-mode-> (c-init-language-vars-for,
c-common-init->(c-basic-common-init,
run some internal hooks, like the "neutralize"), ...)

See existing c-neutralize-syntax-in-CPP initial comment:
"SPEED _MATTERS_ IN THIS FUNCTION!!!"

Profiling confirms - yes, it does. :-)


find-file-noselect            180         3.1810370000  0.0176724277
find-file-noselect-1          180         2.48014       0.0137785555
after-find-file               180         2.1637470000  0.0120208166
normal-mode                   180         2.010236      0.0111679777
set-auto-mode                 180         1.0771709999  0.0059842833
set-auto-mode-0               180         1.0480739999  0.0058226333
c-mode                        180         1.047115      0.0058173055
hack-local-variables          180         0.9007970000  0.0050044277
c-common-init                 180         0.8647119999  0.0048039555
c-neutralize-syntax-in-CPP    180         0.7705030000  0.0042805722
run-hooks                     2357        0.2052220000  8.706...e-05
c-init-language-vars-for      180         0.112398      0.0006244333
c-basic-common-init           180         0.0799130000  0.0004439611
c-neutralize-CPP-line         14000       0.0594100000  4.243...e-06
make-local-variable           10477       0.0177539999  1.694...e-06
set-auto-mode-1               362         0.0149190000  4.121...e-05
kill-all-local-variables      361         0.0091960000  2.547...e-05
c-setup-paragraph-variables   361         0.0060069999  1.663...e-05
c-update-modeline             360         0.005464      1.517...e-05
c-extend-region-for-CPP       180         0.0043769999  2.431...e-05
c-font-lock-init              180         0.0036940000  2.052...e-05
cc-imenu-init                 180         0.0008029999  4.461...e-06
c-initialize-cc-mode          180         0.0003749999  2.083...e-06
easy-menu-add                 180         0.0002349999  1.305...e-06
set-syntax-table              182         0.0001749999  9.615...e-07
use-local-map                 182         0.0001659999  9.120...e-07

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[David De La Harpe Golden]

Lennart Borgman wrote:

> It is probably different on w32 then. It looks like `normal-mode'
> takes maybe 1.5 time insert+file-attr+file-modes+file-exist on w32.
> (But I did not use elp, maybe I missed something.)

I have a vague recollection that emacs' reading of certain file 
attributes can be slow on w32 as it's emulating them or something?
There's a variable w32-get-true-file-attributes that may be relevant?

Reminds me: the ext3 fs I was testing on was mounted "relatime"
http://kerneltrap.org/node/14148
(also turns out NTFS apparently has something very much akin to the 
atime "feature", something I didn't know until just now, might want to 
try turning it off [1])

FWIW, elp - I just added the following to the end of my .emacs

(require 'elp)
(setq elp-function-list
	'(find-file
           find-file-noselect)) ; and so forth.
(elp-set-master 'find-file-noselect)
(elp-instrument-list)

Then, starting emacs with
emacs -l fftest.el -f elp-results
I was presented with my profiling results when they were ready.

(or you can hit M-x elp-results)


[1] no. 8 
http://www.windowsdevcenter.com/pub/a/windows/2005/02/08/NTFS_Hacks.html

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Stefan Monnier]

> Most of the latter is in "hack-project-variables", and most of /that/ is
> "project-find-settings-file", and most of that is the
> "locate-dominating-file" walk.

locate-dominating-file (or rather some equivalent code) is also used in
VC to detect the revision control system used for the file.
It's actually used 5 times there (once each for Bzr Git Hg Mtn Arch), so
are you sure only the one in project-find-settings-file costs us
the slowdown?  If so, it's probably just because it's the first one run
and the others benefit from the OS's cache.


        Stefan

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Eli Zaretskii]

> Date: Fri, 24 Oct 2008 00:33:01 +0200
> From: "Lennart Borgman" <lennart.borgman@gmail.com>
> Cc: "David De La Harpe Golden" <david@harpegolden.net>, acm@muc.de, 
> 	monnier@iro.umontreal.ca, emacs-devel@gnu.org
> 
> (defun test-insert-emacs-lisp-dir ()
>   (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" nil))
>   (message "======================= After cache warm up")
>   (message "Timing insert-file-contents-literally:")
>   (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" t))
>   (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" t))
>   (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" t))
>   (message "Timing insert-file-contents:")
>   (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" nil))
>   (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" nil))
>   (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" nil))
>   (message "Ready"))
> 
> The output was
> 
>   ======================= After cache warm up
>   Timing insert-file-contents-literally:
>   Elapsed time: 5.531000s (0.094000s in 1 GCs)
>   Elapsed time: 5.594000s
>   Elapsed time: 5.828000s (0.093000s in 1 GCs)
>   Timing insert-file-contents:
>   Elapsed time: 9.484000s (0.188000s in 2 GCs)
>   Elapsed time: 8.922000s (0.188000s in 2 GCs)
>   Elapsed time: 8.953000s (0.203000s in 2 GCs)

Thanks.

However, without comparison with Emacs 22, it's hard to interpret
those numbers.

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Eli Zaretskii]

> Date: Thu, 23 Oct 2008 23:47:51 +0100
> From: David De La Harpe Golden <david@harpegolden.net>
> CC: acm@muc.de, monnier@iro.umontreal.ca, emacs-devel@gnu.org
> 
> Haven't got to that that - however, insert-file-contents may only 
> account for < 10% of the total time spent in find-file-noselect-1, at 
> least according to the elp profiler. Though it may not work right at all 
> on C functions? (note doubled call count) - However, I then wrapped the 
> insert-file-contents call in find-file-noselect-1 in an elisp helper 
> function (find-file-noselect-1-h below) and got a quasi-consistent 
> figure for it, see [1] below for results, suggesting it may really be 
> that small?

How do these measurements compare with Emacs 22?

> [Aside: Also turns out upping gc-cons-threshold shaves 2 secs off that 7 
> sec time for 180 files.  Just maybe opening a bunch of files one after 
> the other causes the memory usage to grow rapidly, causing the gc to 
> kick in... so that's one, though probably fairly necessary, slowdown]

Can you try to find out who does so much consing that triggers GC?
And how does this compare with Emacs 22?

TIA

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Eli Zaretskii]

> Date: Fri, 24 Oct 2008 01:12:12 +0200
> From: "Lennart Borgman" <lennart.borgman@gmail.com>
> Cc: "Eli Zaretskii" <eliz@gnu.org>, acm@muc.de, monnier@iro.umontreal.ca, 
> 	emacs-devel@gnu.org
> 
> at the end of `find-file-noselect-1') there are some calls to
> `file-attributes'. Are they perhaps involved?

Set w32-get-true-file-attributes to nil and see if you see any
dramatic changes.  If not, file-attributes is probably not the hot
spot.

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Eli Zaretskii]

> Date: Fri, 24 Oct 2008 01:54:06 +0200
> From: "Lennart Borgman" <lennart.borgman@gmail.com>
> Cc: "Eli Zaretskii" <eliz@gnu.org>, acm@muc.de, monnier@iro.umontreal.ca, 
> 	emacs-devel@gnu.org
> 
>   Timing insert-file-contents-literally:
>   Elapsed time: 8.375000s (0.187000s in 1 GCs)
>   Timing insert-file-contents:
>   Elapsed time: 14.297000s (0.312000s in 2 GCs)
>   Timing file-attributes:
>   Elapsed time: 5.890000s (0.156000s in 1 GCs)
>   Timing file-exists-p:
>   Elapsed time: 6.672000s (0.125000s in 1 GCs)
>   Timing file-modes:
>   Elapsed time: 5.609000s (0.188000s in 1 GCs)

Thanks, but what does this mean?  What is behind a line such as

>   Timing insert-file-contents-literally:
>   Elapsed time: 8.375000s (0.187000s in 1 GCs)

What code was run, how many times, on which files, etc.?

Also, please compare that with Emacs 22, since this whole thread is
about comparative performance.

Thanks.

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Eli Zaretskii]

> Date: Fri, 24 Oct 2008 01:13:42 +0100
> From: David De La Harpe Golden <david@harpegolden.net>
> CC: Eli Zaretskii <eliz@gnu.org>, acm@muc.de, monnier@iro.umontreal.ca, 
>  emacs-devel@gnu.org
> 
> +++ Wasn't the project functionality (.dir-settings.el variable 
> settings) new in emacs23?

Yes, it's new in Emacs 23.

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Eli Zaretskii]

> Date: Fri, 24 Oct 2008 02:44:31 +0100
> From: David De La Harpe Golden <david@harpegolden.net>
> CC: acm@muc.de, Eli Zaretskii <eliz@gnu.org>, monnier@iro.umontreal.ca, 
>  emacs-devel@gnu.org
> 
> David De La Harpe Golden wrote:
> 
> 
> > +++ Which leaves set-auto-mode...
> 
> Which seems to be mostly the particular mode - So of course, this can 
> presumably vary wildly from mode to mode, but let's take c-mode (seeing 
> as it's for the c files I was testing with):
> 
> set-auto-mode->set-auto-mode-0->
> c-mode-> (c-init-language-vars-for,
> c-common-init->(c-basic-common-init,
> run some internal hooks, like the "neutralize"), ...)
> 
> See existing c-neutralize-syntax-in-CPP initial comment:
> "SPEED _MATTERS_ IN THIS FUNCTION!!!"
> 
> Profiling confirms - yes, it does. :-)

How does this compare with Emacs 22?

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Alan Mackenzie]

Hi, David!

First of all, I'm writing this on Friday, ~10:45 UCT.  My ISP's mail
server is having problems, so I don't know when this will get through.
It's somewhat frustrating.  :-(

On Fri, Oct 24, 2008 at 02:44:31AM +0100, David De La Harpe Golden wrote:
> David De La Harpe Golden wrote:


> >+++ Which leaves set-auto-mode...

> Which seems to be mostly the particular mode - So of course, this can 
> presumably vary wildly from mode to mode, but let's take c-mode (seeing 
> as it's for the c files I was testing with):

> set-auto-mode->set-auto-mode-0->
> c-mode-> (c-init-language-vars-for,
> c-common-init->(c-basic-common-init,
> run some internal hooks, like the "neutralize"), ...)

> See existing c-neutralize-syntax-in-CPP initial comment:
> "SPEED _MATTERS_ IN THIS FUNCTION!!!"

> Profiling confirms - yes, it does. :-)

That function's one of mine.  :-)  The story behind the comment is that
my original version of that function was written without consideration
of its speed, and was about two orders of magnitude slower.  People were
complaining, with justification, that it was taking ~1 minute to load a
large file.c.

However, the current function isn't that slow.  I timed it for 100
iterations on a file 2,927,889 bytes big.  It's taking 0.72s for this
file, i.e. about 0.25s per megabyte, and that's on my 1.2 GHz Athlon.

So on emacs/src's 118 files.c, total size 8772802, that function would
take only 2.5s, again, on my Athlon.  On your machine it would be ~0.5s.

Besides, in my original measurements, I was executing the same CC Mode
in Emacs 22 and Emacs 23.

c-neutralize-syntax-in-CPP isn't the problem.

[ .... ]

-- 
Alan Mackenzie (Nuremberg, Germany).

Re: Emacs 23.0 is much slower than Emacs 22.3. Maybe it's the garbage collector.

[Alan Mackenzie]

Hi, emacs.devel!

On Wed, Oct 22, 2008 at 05:02:57PM -0400, Richard M. Stallman wrote:
>     Emacs 23 thus starts up at about three fifths the speed of 22.  This is
>     very noticeable, and not a good thing.
> 
> How about putting code to record the current time
> at a few places in startup.el, in both versions?
> That way you can maybe find out which parts of the code
> have got slower.

Put the following into time-cons.el:
#########################################################################

(let ((c '(0 . 1))
      (n 0))
  (while (< n 10000000) ; ten million
    (setq c (cons 0 n))
    (setq n (1+ n)))
  c)
      
#########################################################################

Now run
time emacs -Q -batch -l time-cons.el

        Emacs 22        Emacs 23
real    0m23.603s       0m32.733s
user    0m23.523s       0m32.595s 
sys     0m0.019s        0m0.053s 

[David: You might want to try 100 million, or even 10^9.  :-]

Is ten million conses enough to trigger garbage collection?  If so,
that could be a problematic area.

However, the following gave the same timings on both 22 and 23:
#########################################################################

(let ((c '(0 . 1))
      (n 0))
  (while (< n 10000000) ; ten million
    (setcdr c n)
    (setq n (1+ n)))
  c)
  
#########################################################################
      

-- 
Alan Mackenzie (Nuremberg, Germany).

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[David De La Harpe Golden]

Eli Zaretskii wrote:

> Also, please compare that with Emacs 22, since this whole thread is
> about comparative performance.
> 
> Thanks.


Hey now, that may be some thread participants' only concern, but I 
already noted my concern with the absolute performance...

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[David De La Harpe Golden]

Alan Mackenzie wrote:

> However, the current function isn't that slow.  I timed it for 100
> iterations on a file 2,927,889 bytes big.  It's taking 0.72s for this
> file, i.e. about 0.25s per megabyte, and that's on my 1.2 GHz Athlon.
> 
> So on emacs/src's 118 files.c, total size 8772802, that function would
> take only 2.5s, again, on my Athlon.  On your machine it would be ~0.5s.
> 
> Besides, in my original measurements, I was executing the same CC Mode
> in Emacs 22 and Emacs 23.
> 
> c-neutralize-syntax-in-CPP isn't the problem.
>

Probably not, or at least not the slowdown you're seeing i.e. your 
relative emacs22/23 problem.  N.B. It wasn't intended as a slight - I do 
appreciate C is a relative pain to parse, syntax-highlight and deal with 
in general, I'm_ not_ saying c-mode's apparently associated overhead is 
necessarily unreasonable,  but it may explain why stuff I was generally 
doing in emacs day-to-day seemed to load a little bit faster than this 
particular test case (if you recall, I was surprised at the result) - I 
relatively seldom edit c files!  But c-mode as a whole _does_ account 
for a significant chunk of the startup time on the 180 .c files I was 
testing with:

time emacs -l fftest.el -f kill-emacs
with in .emacs  a sneaky
(setq auto-mode-alist (cons (cons "\\.c\\'" 'text-mode) 	auto-mode-alist))

emacs c-mode	realtime
22	on	4.951
23	on	7.388
22	off	2.830
23	off	4.089

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[David De La Harpe Golden]

Eli Zaretskii wrote:
>> Date: Fri, 24 Oct 2008 02:44:31 +0100
>> From: David De La Harpe Golden <david@harpegolden.net>
>> CC: acm@muc.de, Eli Zaretskii <eliz@gnu.org>, monnier@iro.umontreal.ca, 
>>  emacs-devel@gnu.org
>>
>> David De La Harpe Golden wrote:
>>
>>
>>> +++ Which leaves set-auto-mode...
>> Which seems to be mostly the particular mode - So of course, this can 
>> presumably vary wildly from mode to mode, but let's take c-mode (seeing 
>> as it's for the c files I was testing with):
>>
>> set-auto-mode->set-auto-mode-0->
>> c-mode-> (c-init-language-vars-for,
>> c-common-init->(c-basic-common-init,
>> run some internal hooks, like the "neutralize"), ...)
>>
>> See existing c-neutralize-syntax-in-CPP initial comment:
>> "SPEED _MATTERS_ IN THIS FUNCTION!!!"
>>
>> Profiling confirms - yes, it does. :-)
> 
> How does this compare with Emacs 22?

(gc-cons-threshold @ 1G as it was for the emacs23 test your replied to)

As you can see by comparing the two, the "set-auto-mode" path of 
"normal-mode" is  similar overhead on both but "hack-local-variables" is 
about 27 TIMES slower on emacs23...

Function Name                 Call Count  Elapsed Time  Average Time
============================  ==========  ============  ============
find-file-noselect            180         2.2096209999  0.0122756722
find-file-noselect-1          180         1.4848800000  0.0082493333
after-find-file               180         1.226164      0.0068120222
normal-mode                   180         0.9997670000  0.0055542611
set-auto-mode                 180         0.9343669999  0.0051909277
set-auto-mode-0               180         0.9077470000  0.0050430388
c-mode                        180         0.9068940000  0.0050383000
c-common-init                 180         0.6864290000  0.0038134944
c-neutralize-syntax-in-CPP    182         0.5930520000  0.0032585274
run-hooks                     1998        0.2834299999  0.0001418568
c-init-language-vars-for      180         0.1180209999  0.0006556722
c-basic-common-init           180         0.0789910000  0.0004388388
c-neutralize-CPP-line         14000       0.0531670000  3.797...e-06
hack-local-variables          181         0.0335519999  0.0001853701
easy-menu-add                 180         0.0288129999  0.0001600722
make-local-variable           11046       0.0169949999  1.538...e-06
set-auto-mode-1               363         0.0139350000  3.838...e-05
kill-all-local-variables      361         0.0090380000  2.503...e-05
c-setup-paragraph-variables   361         0.0067259999  1.863...e-05
c-update-modeline             360         0.0059999999  1.666...e-05
c-extend-region-for-CPP       182         0.0048190000  2.647...e-05
c-font-lock-init              180         0.0033029999  1.834...e-05
cc-imenu-init                 180         0.0009289999  5.161...e-06
c-initialize-cc-mode          180         0.0004939999  2.744...e-06
c-after-change                2           0.000241      0.0001205
use-local-map                 182         0.0001749999  9.615...e-07
set-syntax-table              182         0.0001529999  8.406...e-07
c-before-change               2           0.000103      5.15e-05
c-extend-after-change-region  2           3e-06         1.5e-06

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[David De La Harpe Golden]

Stefan Monnier wrote:
>> Most of the latter is in "hack-project-variables", and most of /that/ is
>> "project-find-settings-file", and most of that is the
>> "locate-dominating-file" walk.
> 
> locate-dominating-file (or rather some equivalent code) is also used in
> VC to detect the revision control system used for the file.
> It's actually used 5 times there (once each for Bzr Git Hg Mtn Arch), so
> are you sure only the one in project-find-settings-file costs us
> the slowdown?  

Not all of it, but it seems to be significant.

taking out locate-dominating-file with:
(defun locate-dominating-file (file regexp) nil)

runs just now (one after the other, no reboot, so probably
from OS cache anyway)

emacs 	l-d-f	realtime
22	n/a	4.921
23	off	6.188
23	on	7.500

Taking out hack-project-variables as a whole similarly

emacs 	h-p-v	realtime
23	off	6.079

So it's about 1/2 the slowdown?

Then I set vc-handled-backends to nil (not sure that stops
vc searching totally, mind):

emacs vc-h-b 	h-p-v	realtime
23    off 	off	5.503
23    off	on	7.189

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Lennart Borgman]

On Fri, Oct 24, 2008 at 11:51 AM, Eli Zaretskii <eliz@gnu.org> wrote:
>> Date: Fri, 24 Oct 2008 01:54:06 +0200
>> From: "Lennart Borgman" <lennart.borgman@gmail.com>
>> Cc: "Eli Zaretskii" <eliz@gnu.org>, acm@muc.de, monnier@iro.umontreal.ca,
>>       emacs-devel@gnu.org
>>
>>   Timing insert-file-contents-literally:
>>   Elapsed time: 8.375000s (0.187000s in 1 GCs)
>>   Timing insert-file-contents:
>>   Elapsed time: 14.297000s (0.312000s in 2 GCs)
>>   Timing file-attributes:
>>   Elapsed time: 5.890000s (0.156000s in 1 GCs)
>>   Timing file-exists-p:
>>   Elapsed time: 6.672000s (0.125000s in 1 GCs)
>>   Timing file-modes:
>>   Elapsed time: 5.609000s (0.188000s in 1 GCs)
>
> Thanks, but what does this mean?  What is behind a line such as

Here is the code again, a little bit enhanced:

(defun test-insert-dir (dir how)
  (let ((files (directory-files dir t)))
    (dolist (file files)
      (unless (file-directory-p file)
        (with-temp-buffer
          (cond
           ((eq how 'literally)
            (insert-file-contents-literally file))
           ((eq how 'normal-insert)
            (insert-file-contents file))
           ((eq how 'attributes)
            (file-attributes file))
           ((eq how 'exists)
            (file-exists-p file))
           ((eq how 'file-modes)
            (file-exists-p file))
           ((eq how 'normal-mode)
            (setq buffer-file-name file)
            (emacs-lisp-mode)
            (setq buffer-file-name nil)
            (set-buffer-modified-p nil))
           (t
            (error "How=%s" how))
           ))))))

(defun test-insert-emacs-lisp-dir ()
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" 'literally))
  (message "======================= After cache warm up")
  (message "Timing insert-file-contents-literally:")
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" 'literally))
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" 'literally))
  (message "Timing insert-file-contents:")
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/"
'normal-insert))
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/"
'normal-insert))
  (message "Timing file-attributes:")
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" 'attributes))
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" 'attributes))
  (message "Timing file-exists-p:")
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" 'exists))
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" 'exists))
  (message "Timing file-modes:")
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" 'file-modes))
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" 'file-modes))
  (message "Timing normal-mode:")
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" 'normal-mode))
  (benchmark 1 '(test-insert-dir "c:/emacs/u/070103/emacs/lisp/" 'normal-mode))
  (message "Ready"))

> Also, please compare that with Emacs 22, since this whole thread is
> about comparative performance.

In Emacs 22 I get in *Messages* buffer:

  ======================= After cache warm up
  Timing insert-file-contents-literally:
  Elapsed time: 3.172000s (0.031000s in 1 GCs)
  Elapsed time: 3.141000s (0.032000s in 1 GCs)
  Timing insert-file-contents:
  Elapsed time: 4.609000s (0.125000s in 4 GCs)
  Elapsed time: 4.610000s (0.125000s in 4 GCs)
  Timing file-attributes:
  Elapsed time: 1.859000s (0.031000s in 1 GCs)
  Elapsed time: 1.891000s (0.015000s in 1 GCs)
  Timing file-exists-p:
  Elapsed time: 1.875000s (0.016000s in 1 GCs)
  Elapsed time: 1.968000s (0.016000s in 1 GCs)
  Timing file-modes:
  Elapsed time: 2.063000s (0.031000s in 1 GCs)
  Elapsed time: 1.859000s (0.031000s in 1 GCs)
  Timing normal-mode:
  Elapsed time: 1.235000s (0.048000s in 2 GCs)
  Elapsed time: 1.437000s (0.016000s in 1 GCs)

and in Emacs 23:

  ======================= After cache warm up
  Timing insert-file-contents-literally:
  Elapsed time: 4.844000s
  Elapsed time: 4.828000s (0.109000s in 1 GCs)
  Timing insert-file-contents:
  Elapsed time: 8.094000s (0.109000s in 1 GCs)
  Elapsed time: 8.063000s (0.219000s in 2 GCs)
  Timing file-attributes:
  Elapsed time: 3.796000s
  Elapsed time: 3.579000s (0.094000s in 1 GCs)
  Timing file-exists-p:
  Elapsed time: 3.515000s
  Elapsed time: 3.578000s (0.109000s in 1 GCs)
  Timing file-modes:
  Elapsed time: 3.625000s
  Elapsed time: 3.953000s (0.109000s in 1 GCs)
  Timing normal-mode:
  Mark set [553 times]
  Elapsed time: 3.985000s (0.891000s in 9 GCs)
  Mark set [553 times]
  Elapsed time: 6.031000s (1.810000s in 18 GCs)

The system calls (file-attributes, file-exists-p and file-modes) takes
nearly twice as long time in Emacs 23 (on w32). For normal-mode the
factor is even bigger, 3-4 times longer time.

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Chong Yidong]

"Lennart Borgman" <lennart.borgman@gmail.com> writes:

> The system calls (file-attributes, file-exists-p and file-modes) takes
> nearly twice as long time in Emacs 23 (on w32). For normal-mode the
> factor is even bigger, 3-4 times longer time.

Could you try testing file-attributes, file-exists-p and file-modes in
isolation, to see which one of the three are slower (or is it all
three)?

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[David De La Harpe Golden]

Lennart Borgman wrote:
> On Fri, Oct 24, 2008 at 11:51 AM, Eli Zaretskii <eliz@gnu.org> wrote:
>>> Date: Fri, 24 Oct 2008 01:54:06 +0200
>>> From: "Lennart Borgman" <lennart.borgman@gmail.com>
>>> Cc: "Eli Zaretskii" <eliz@gnu.org>, acm@muc.de, monnier@iro.umontreal.ca,
>>>       emacs-devel@gnu.org
>>>
>>>   Timing insert-file-contents-literally:
>>>   Elapsed time: 8.375000s (0.187000s in 1 GCs)
>>>   Timing insert-file-contents:
>>>   Elapsed time: 14.297000s (0.312000s in 2 GCs)
>>>   Timing file-attributes:
>>>   Elapsed time: 5.890000s (0.156000s in 1 GCs)
>>>   Timing file-exists-p:
>>>   Elapsed time: 6.672000s (0.125000s in 1 GCs)
>>>   Timing file-modes:
>>>   Elapsed time: 5.609000s (0.188000s in 1 GCs)
>> Thanks, but what does this mean?  What is behind a line such as
> 
> Here is the code again, a little bit enhanced:

FWIW, ran your code on my debian/unstable amd64 system using linux 
kernel 2.6.26 (though using /usr/local/src/emacs/lisp rather than 
c:«blah» for obvious reasons), results below (no gc or function stubbing 
tweaks).  The file attributes are a w32-specific problem I guess - are 
(a) about 40x faster than your w32 emacs23 and (b) similar between 
emacs22/23 (actually slightly faster with 23 in the test runs, but that 
could just be the GC and general noise).

OTOH the normal-mode call is noticeably slower for emacs23 (though
not as pronounced as on your w32 - of course, the emacs23 normal-mode 
code path includes more file attribute usage due to the .dir.settings.el 
stuff...)

Emacs 22:
======================= After cache warm up
Timing insert-file-contents-literally:
Elapsed time: 0.403781s (0.031159s in 1 GCs)
Elapsed time: 0.433654s (0.061884s in 2 GCs)
Timing insert-file-contents:
Elapsed time: 1.073601s (0.127081s in 4 GCs)
Elapsed time: 1.066970s (0.125150s in 4 GCs)
Timing file-attributes:
Elapsed time: 0.099218s (0.031007s in 1 GCs)
Elapsed time: 0.131247s (0.062046s in 2 GCs)
Timing file-exists-p:
Elapsed time: 0.132959s (0.062106s in 2 GCs)
Elapsed time: 0.101442s (0.031064s in 1 GCs)
Timing file-modes:
Elapsed time: 0.133818s (0.062778s in 2 GCs)
Elapsed time: 0.101579s (0.031122s in 1 GCs)
Timing normal-mode:
Elapsed time: 0.176703s (0.062539s in 2 GCs)
Elapsed time: 0.257191s (0.065307s in 2 GCs)
Ready


Emacs 23:
======================= After cache warm up
Timing insert-file-contents-literally:
Elapsed time: 0.296811s (0.052762s in 1 GCs)
Elapsed time: 0.293286s (0.051887s in 1 GCs)
Timing insert-file-contents:
Elapsed time: 1.183911s (0.160524s in 3 GCs)
Elapsed time: 1.179618s (0.161070s in 3 GCs)
Timing file-attributes:
Elapsed time: 0.092713s (0.052083s in 1 GCs)
Elapsed time: 0.092785s (0.051292s in 1 GCs)
Timing file-exists-p:
Elapsed time: 0.094927s (0.051904s in 1 GCs)
Elapsed time: 0.095253s (0.051449s in 1 GCs)
Timing file-modes:
Elapsed time: 0.096032s (0.052696s in 1 GCs)
Elapsed time: 0.094715s (0.051999s in 1 GCs)
Timing normal-mode:
Elapsed time: 0.245259s (0.104135s in 2 GCs)
Elapsed time: 0.390639s (0.107556s in 2 GCs)
Ready

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Eli Zaretskii]

> From: Chong Yidong <cyd@stupidchicken.com>
> Cc: "Eli Zaretskii" <eliz@gnu.org>,  acm@muc.de,  emacs-devel@gnu.org,  monnier@iro.umontreal.ca,  david@harpegolden.net
> Date: Fri, 24 Oct 2008 12:24:58 -0400
> 
> "Lennart Borgman" <lennart.borgman@gmail.com> writes:
> 
> > The system calls (file-attributes, file-exists-p and file-modes) takes
> > nearly twice as long time in Emacs 23 (on w32). For normal-mode the
> > factor is even bigger, 3-4 times longer time.
> 
> Could you try testing file-attributes, file-exists-p and file-modes in
> isolation, to see which one of the three are slower (or is it all
> three)?

They all call `stat', so on Windows they all are similarly expensive.

It is on my todo to request a cheap version of `stat' in almost every
function that calls `stat' except file-attributes and a couple of
others, which _really_ need the whole attribute set.

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Eli Zaretskii]

> Date: Fri, 24 Oct 2008 17:45:09 +0100
> From: David De La Harpe Golden <david@harpegolden.net>
> CC: Eli Zaretskii <eliz@gnu.org>, acm@muc.de, monnier@iro.umontreal.ca, 
>  emacs-devel@gnu.org
> 
> The file attributes are a w32-specific problem I guess

On Posix systems, `stat' (called by file-attributes) is a system call,
so it obviously doesn't depend on the Emacs versions.  By contrast, on
Windows we emulate `stat' with several quite expensive system calls.

Thus, it is meaningless to compare GNU/Linux and Windows as far as
file-attributes is concerned.

> (a) about 40x faster than your w32 emacs23 and (b) similar between 
> emacs22/23 (actually slightly faster with 23 in the test runs, but that 
> could just be the GC and general noise).

Yes, none of these primitives is the hot spot.

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Stefan Monnier]

>>> Most of the latter is in "hack-project-variables", and most of /that/ is
>>> "project-find-settings-file", and most of that is the
>>> "locate-dominating-file" walk.
>> locate-dominating-file (or rather some equivalent code) is also used in
>> VC to detect the revision control system used for the file.
>> It's actually used 5 times there (once each for Bzr Git Hg Mtn Arch), so
>> are you sure only the one in project-find-settings-file costs us
>> the slowdown?  

> Not all of it, but it seems to be significant.

> taking out locate-dominating-file with:
> (defun locate-dominating-file (file regexp) nil)

> runs just now (one after the other, no reboot, so probably
> from OS cache anyway)

> emacs 	l-d-f	realtime
> 22	n/a	4.921
> 23	off	6.188
> 23	on	7.500

> Taking out hack-project-variables as a whole similarly

> emacs 	h-p-v	realtime
> 23	off	6.079

> So it's about 1/2 the slowdown?

> Then I set vc-handled-backends to nil (not sure that stops
> vc searching totally, mind):

> emacs vc-h-b 	h-p-v	realtime
> 23    off 	off	5.503
> 23    off	on	7.189

Setting vc-handled-backends to nil should indeed stop VC from doing
those directory walks.  So now I don't understand why the walks done by
VC are so much cheaper than the ones done by locate-dominating-file.
Could it be that all the files you opened were under CVS control (so
the VC search stops before having to walk up the directories)?


        Stefan

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Alan Mackenzie]

Hi, David!

On Fri, Oct 24, 2008 at 03:32:30PM +0100, David De La Harpe Golden wrote:
> Alan Mackenzie wrote:

[ .... ]

> >c-neutralize-syntax-in-CPP isn't the problem.

> Probably not, or at least not the slowdown you're seeing i.e. your
> relative emacs22/23 problem.  N.B. It wasn't intended as a slight - I
> do appreciate C is a relative pain to parse, syntax-highlight and deal
> with in general, .....

Thanks!

> ...., I'm_ not_ saying c-mode's apparently associated overhead is
> necessarily unreasonable,  but it may explain why stuff I was generally
> doing in emacs day-to-day seemed to load a little bit faster than this
> particular test case (if you recall, I was surprised at the result) - I
> relatively seldom edit c files!  But c-mode as a whole _does_ account
> for a significant chunk of the startup time on the 180 .c files I was
> testing with:

Good!

> time emacs -l fftest.el -f kill-emacs
> with in .emacs  a sneaky
> (setq auto-mode-alist (cons (cons "\\.c\\'" 'text-mode)  auto-mode-alist))

> emacs c-mode	realtime
> 22	on	4.951
> 23	on	7.388
> 22	off	2.830
> 23	off	4.089

That's something like I would expect.

By the way, did you see my other post in this thread (Subject: expanded a
bit), where I did a test creating 10,000,000 conses, and Emacs 23 was
appreciably slower than Emacs 22?  I suspect the garbage collector.

-- 
Alan Mackenzie (Nuremberg, Germany).

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[David De La Harpe Golden]

Alan Mackenzie wrote:

> By the way, did you see my other post in this thread (Subject: expanded a
> bit), where I did a test creating 10,000,000 conses, and Emacs 23 was
> appreciably slower than Emacs 22?  I suspect the garbage collector.
> 

in turn did you see my post re 
hack-project-variables/locate-dominating-file?

Can you try on your system your test with a
(defun hack-project-variables () nil)  in your .emacs?

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[David De La Harpe Golden]

Stefan Monnier wrote:


> Could it be that all the files you opened were under CVS control (so
> the VC search stops before having to walk up the directories)?
> 

That sounded quite plausible - seeing as I was testing in an emacs CVS 
source tree checkout and all. Though it was only in /usr/local/src/emacs 
- and /usr/local is the same fs as / on my desktop.

So I redid in the emacs-22.3 expanded source tarball (no ./CVS ?)
in /usr/local/src/emacs-22-3  (187 .c files this time)

hack-project-variables vc-handled-backends

emacs	vc-h-b h-p-v	realtime
23	off	off	5.959
23	off	on	7.629
23	on	off	5.916
23	on	on	7.720

Er. Maybe I should use a bigger corpus... - so, did all .el files (1108 
files).

emacs vc-h-b h-p-v	realtime
23	off	off	21.170
23	off	on	36.346
23	on 	off	23.510
23	on 	on	38.566

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[David De La Harpe Golden]

[-- Attachment #1: Type: text/plain, Size: 2599 bytes --]

Stefan Monnier wrote:
> 
> Setting vc-handled-backends to nil should indeed stop VC from doing
> those directory walks.  So now I don't understand why the walks done by
> VC are so much cheaper than the ones done by locate-dominating-file.
> Could it be that all the files you opened were under CVS control (so
> the VC search stops before having to walk up the directories)?
> 
> 

Eventually found vc-find-root. So - it versus locate-dominating-file ?

While they're doing a fairly similar job, they do look to me like 
they're implemented importantly differently -locate-dominating-file 
takes a regex and passes it to directory-files for each directory. 
AFAICS directory-files scans the whole directory each time through for 
the match. OTOH, vc-find-root just tests if /path/to/directory/witness 
exists.  The former is rather slower and (I think) consier. I'm not sure 
   that there's any real performance problem with directory-files itself 
for what it actually does, though maybe it could be made faster. Maybe 
not worthwhile though - easier to rewrite locate-dominating-file to not 
use it as below...

Profiling says locate-dominating-file is spending most all its time  in 
directory-files trying that doomed match again and again...

find-file-noselect         1108        48.279532999  0.0435735857
find-file-noselect-1       1108        29.139766999  0.0262994287
after-find-file            1108        26.323623999  0.0237577833
normal-mode                1108        21.492128000  0.0193972274
hack-local-variables       1108        19.570003     0.0176624575
hack-project-variables     1108        19.266695999  0.0173887148
project-find-settings-file 1108        19.254854999  0.0173780279
locate-dominating-file     1108        19.237415000  0.0173622879
directory-files            4152        18.688168999  0.0045010040


So is locate-dominating-file's regex-matching really necessary in 
project-find-settings-file? The only call to locate-dominating-file I 
can see is it just searching for a (hardcoded name) ".dir.settings.el" 
in project-find-settings-file, so vc-find-root's rather simpler witness 
technique would work just fine?

+++ And indeed, attached patch makes emacs23 1108-file-startup rather 
more competitive with emacs22 on my system. Though I didn't do much 
testing to see if project settings functionality was 100% a-okay -
though it seemed to pick up a /usr/local/src/emacs-22.3/.dir-settings.el
I made okay...

emacs   patch 	withsettings 	realtime
22	n/a	n/a		22.853
23	no	no 		38.518
23	no	yes		38.729
23	yes  	no		23.295
23	yes	yes		23.340










[-- Attachment #2: emacs-faster-locate-dominating-file.diff --]
[-- Type: text/x-patch, Size: 4135 bytes --]

Index: lisp/files.el
===================================================================
RCS file: /sources/emacs/emacs/lisp/files.el,v
retrieving revision 1.1005
diff -U 8 -r1.1005 files.el
--- lisp/files.el	18 Oct 2008 18:40:25 -0000	1.1005
+++ lisp/files.el	24 Oct 2008 23:37:19 -0000
@@ -711,18 +711,59 @@
 (defun locate-file-completion (string path-and-suffixes action)
   "Do completion for file names passed to `locate-file'.
 PATH-AND-SUFFIXES is a pair of lists, (DIRECTORIES . SUFFIXES)."
   (locate-file-completion-table (car path-and-suffixes)
                                 (cdr path-and-suffixes)
                                 string nil action))
 (make-obsolete 'locate-file-completion 'locate-file-completion-table "23.1")
 
-(defun locate-dominating-file (file regexp)
-  "Look up the directory hierarchy from FILE for a file matching REGEXP."
+(defun locate-dominating-file (file name)
+   "Look up the directory hierarchy from FILE for a file named NAME.
+If found, return the file named NAME's full name and path, otherwise
+return nil. See locate-dominating-file-by-regexp if you have more
+complex requirements than a simple whole-string match on the name,
+though beware it is slower."
+   ;; copied from vc-find-root, then changed to return file
+   ;; rather than containing dir.
+   ;; Represent /home/luser/foo as ~/foo so that we don't try to look for
+   ;; witnesses in /home or in /.
+   (setq file (abbreviate-file-name file))
+   (let ((root nil)
+	 (prev-file file)
+	 ;; `user' is not initialized outside the loop because
+	 ;; `file' may not exist, so we may have to walk up part of the
+	 ;; hierarchy before we find the "initial UID".
+	 (user nil)
+	 try)
+     (while (not (or root
+		     (null file)
+		     ;; As a heuristic, we stop looking up the hierarchy of
+		     ;; directories as soon as we find a directory belonging
+		     ;; to another user.  This should save us from looking in
+		     ;; things like /net and /afs.  This assumes that all the
+		     ;; files inside a project belong to the same user.
+		     (let ((prev-user user))
+		       (setq user (nth 2 (file-attributes file)))
+		       (and prev-user (not (equal user prev-user))))
+		     (string-match
+		      ;; from vc-ignore-dir-regexp !
+		      "\\`\\(?:[\\/][\\/]\\|/\\(?:net\\|afs\\|\\.\\.\\.\\)/\\)\\'"
+		      file)))
+       (setq try (file-exists-p (expand-file-name name file)))
+       (cond (try (setq root file))
+	     ((equal file (setq prev-file file
+				file (file-name-directory
+				      (directory-file-name file))))
+	      (setq file nil))))
+     (when root (expand-file-name name root))))
+
+(defun locate-dominating-file-by-regexp (file regexp)
+  "Look up the directory hierarchy from FILE for a file matching REGEXP.
+This function is slower than `locate-dominating-file', only use if necessary."
   (catch 'found
     ;; `user' is not initialized yet because `file' may not exist, so we may
     ;; have to walk up part of the hierarchy before we find the "initial UID".
     (let ((user nil)
           ;; Abbreviate, so as to stop when we cross ~/.
           (dir (abbreviate-file-name (file-name-as-directory file)))
           files)
       (while (and dir
@@ -3154,17 +3195,17 @@
 (defun project-find-settings-file (file)
   "Find the settings file for FILE.
 This searches upward in the directory tree.
 If a settings file is found, the file name is returned.
 If the file is in a registered project, a cons from
 `project-directory-alist' is returned.
 Otherwise this returns nil."
   (setq file (expand-file-name file))
-  (let* ((settings (locate-dominating-file file "\\`\\.dir-settings\\.el\\'"))
+  (let* ((settings (locate-dominating-file file ".dir-settings.el"))
          (pda nil))
     ;; `locate-dominating-file' may have abbreviated the name.
     (if settings (setq settings (expand-file-name settings)))
     (dolist (x project-directory-alist)
       (when (and (eq t (compare-strings file nil (length (car x))
                                         (car x) nil nil))
                  (> (length (car x)) (length (car pda))))
         (setq pda x)))

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Richard M. Stallman]

    OTOH the normal-mode call is noticeably slower for emacs23 (though
    not as pronounced as on your w32 - of course, the emacs23 normal-mode 
    code path includes more file attribute usage due to the .dir.settings.el 
    stuff...)

Does `normal-mode' look for the that file more than once in a given
directory?  If so, that is an easy optimization: record the directories
in which it has looked for that file, and don't look again.

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[David De La Harpe Golden]

Richard M. Stallman wrote:

> Does `normal-mode' look for the that file more than once in a given
> directory? 

AFAIK it shouldn't in a given call. Across calls caching the
info would be wrong* since a user might happen to make a
.dir-settings.el in the interim. Anyway, as per recent previous mail 
with patch [1] the issue was with _how_ the filename was being looked 
for in the directory - ask for every filename in the directory and 
iterate through checking if one regex-matches (directory-files, slower) 
or ask if the directory has a file called filename in it (file-exists-p, 
faster).

* well, could have a smart cache with inotify (or
other-oses-equivalent). http://en.wikipedia.org/wiki/Inotify
"function is essentially an extension to filesystems to notice changes
to the filesystem, and report those changes to applications.",
... and/or a batch interface that signals that a bunch of files are
about to be opened in one go and it's okay to cache for a bit...
... but maybe not worth the bother in this instance...


[1] Message-ID: <49025DF8.6030502@harpegolden.net>

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[Stefan Monnier]

>> Setting vc-handled-backends to nil should indeed stop VC from doing
>> those directory walks.  So now I don't understand why the walks done by
>> VC are so much cheaper than the ones done by locate-dominating-file.
>> Could it be that all the files you opened were under CVS control (so
>> the VC search stops before having to walk up the directories)?

> Eventually found vc-find-root. So - it versus locate-dominating-file ?
> While they're doing a fairly similar job, they do look to me like they're
> implemented importantly differently -locate-dominating-file takes a regex
> and passes it to directory-files for each directory. AFAICS directory-files
> scans the whole directory each time through for the match. OTOH,
> vc-find-root just tests if /path/to/directory/witness exists.  The former is
> rather slower and (I think) consier. I'm not sure that there's any real
> performance problem with directory-files itself for what it actually does,
> though maybe it could be made faster. Maybe not worthwhile though - easier
> to rewrite locate-dominating-file to not use it as below...

Thanks for you investigative work.  locate-dominating-file used a regexp
for searches for multiple files (e.g. I intended to merge the N calls to
vc-find-root into a single call to locate-dominating-file), but from
your measurements, it seems that unless we're searching for an
open-ended set of files we're better off with multiple calls to
vc-find-root, so I think we should indeed change locate-dominating-file
to use a fixed name.  This will also have the advantage that we should
be able to use it directory for VC and hence get rid of vc-find-root.

I've installed a change which should do just that.


        Stefan

Re: Emacs 23.0 is much slower starting than Emacs 22.3

[David De La Harpe Golden]

Stefan Monnier wrote:

> Thanks for you investigative work. 

You're welcome!

It should be stressed they were results from my system, of course other 
systems and OSes may have quite different characteristics and 
performance problems (as we see with w32).