bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Eli Zaretskii]

This bug report will be sent to the Bug-GNU-Emacs mailing list
and the GNU bug tracker at debbugs.gnu.org.  Please check that
the From: line contains a valid email address.  After a delay of up
to one day, you should receive an acknowledgement at that address.

Please write in English if possible, as the Emacs maintainers
usually do not have translators for other languages.

Please describe exactly what actions triggered the bug, and
the precise symptoms of the bug.  If you can, give a recipe
starting from `emacs -Q':

The byte compiler seems to be a lot slower now, when run interpreted,
compared with how it was a couple of weeks ago.  With the current
trunk:

  D:\gnu\bzr\emacs\trunk\lisp>timep ..\bin\bootstrap-emacs -batch -f batch-byte-compile org\org.el

  In toplevel form:
  org/org.el:4874:1:Warning: global/dynamic var `entry' lacks a prefix
  org/org.el:4876:1:Warning: global/dynamic var `date' lacks a prefix
  Wrote d:/gnu/bzr/emacs/trunk/lisp/org/org.elc

  real    00h00m16.343s
  user    00h00m16.234s
  sys     00h00m00.093s

With trunk revision 108318:

  D:\gnu\bzr\emacs\test2\lisp>timep ..\bin\bootstrap-emacs -batch -f batch-byte-compile org\org.el

  In toplevel form:
  org/org.el:4873:1:Warning: global/dynamic var `entry' lacks a prefix
  org/org.el:4875:1:Warning: global/dynamic var `date' lacks a prefix
  Wrote d:/gnu/bzr/emacs/test2/lisp/org/org.elc

  real    00h00m02.125s
  user    00h00m02.046s
  sys     00h00m00.093s

That's a 8-fold slowdown.  Consequently, the bootstrap time on
MS-Windows went up from 9 minutes to 33 minutes, which is gross.

I see a similar slowdown on a x86_64 GNU/Linux machine.  Here's a
comparison with the latest emacs-24 branch:

  eliz@fencepost:~/bzr/emacs/trunk$ time ./src/bootstrap-emacs2 -batch -f batch-byte-compile lisp/org/org.el

  In toplevel form:
  lisp/org/org.el:4874:1:Warning: global/dynamic var `entry' lacks a prefix
  lisp/org/org.el:4876:1:Warning: global/dynamic var `date' lacks a prefix
  Wrote /home/e/eliz/bzr/emacs/trunk/lisp/org/org.elc

  real    0m47.939s
  user    0m45.850s
  sys     0m0.340s

  eliz@fencepost:~/bzr/emacs/emacs-24$ time ./src/bootstrap-emacs2 -batch -f batch-byte-compile lisp/org/org.el

  In toplevel form:
  org.el:4874:1:Warning: global/dynamic var `entry' lacks a prefix
  org.el:4876:1:Warning: global/dynamic var `date' lacks a prefix
  Wrote /home/e/eliz/bzr/emacs/emacs-24/lisp/org/org.elc

  real    0m5.883s
  user    0m5.620s
  sys     0m0.140s

There's no perceptible change in speed of the byte compiler when it is
run after being compiled.  I get the same times, plus or minus the
measurement noise, on both Windows and GNU/Linux.

Is this slowdown expected?  Can it be fixed?

If Emacs crashed, and you have the Emacs process in the gdb debugger,
please include the output from the following gdb commands:
    `bt full' and `xbacktrace'.
For information about debugging Emacs, please read the file
d:/gnu/bzr/emacs/trunk/etc/DEBUG.


In GNU Emacs 24.1.50.1 (i386-mingw-nt5.1.2600)
 of 2012-06-09 on HOME-C4E4A596F7
Bzr revision: 108534 cyd@gnu.org-20120609062646-n059z024eqc4npxy
Windowing system distributor `Microsoft Corp.', version 5.1.2600
Configured using:
 `configure --with-gcc (3.4) --no-opt --enable-checking --cflags
 -Id:/usr/include/libxml2 -DGLYPH_DEBUG=1'

Important settings:
  value of $EMACSDATA: D:/gnu/bzr/emacs/trunk/etc
  value of $EMACSDOC: D:/gnu/bzr/emacs/trunk/etc
  value of $EMACSLOADPATH: D:/gnu/bzr/emacs/trunk/lisp;D:/gnu/bzr/emacs/trunk/leim
  value of $EMACSPATH: D:/gnu/bzr/emacs/trunk/bin
  value of $LANG: ENU
  locale-coding-system: cp1255
  default enable-multibyte-characters: t

Major mode: Lisp Interaction

Minor modes in effect:
  tooltip-mode: t
  mouse-wheel-mode: t
  tool-bar-mode: t
  menu-bar-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  blink-cursor-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  line-number-mode: t
  transient-mark-mode: t

Recent input:
M-x e m a c s - <M-backspace> r e p o r t - e m <tab> 
<return>

Recent messages:
For information about GNU Emacs and the GNU system, type C-h C-a.

Load-path shadows:
None found.

Features:
(shadow sort gnus-util mail-extr emacsbug message format-spec rfc822 mml
easymenu mml-sec mm-decode mm-bodies mm-encode mail-parse rfc2231
mailabbrev gmm-utils mailheader sendmail rfc2047 rfc2045 ietf-drums
mm-util mail-prsvr mail-utils time-date tooltip ediff-hook vc-hooks
lisp-float-type mwheel dos-w32 disp-table ls-lisp w32-win w32-vars
tool-bar dnd fontset image regexp-opt fringe tabulated-list newcomment
lisp-mode register page menu-bar rfn-eshadow timer select scroll-bar
mouse jit-lock font-lock syntax facemenu font-core frame cham georgian
utf-8-lang misc-lang vietnamese tibetan thai tai-viet lao korean
japanese hebrew greek romanian slovak czech european ethiopic indian
cyrillic chinese case-table epa-hook jka-cmpr-hook help simple abbrev
minibuffer button faces cus-face files text-properties overlay sha1 md5
base64 format env code-pages mule custom widget hashtable-print-readable
backquote make-network-process multi-tty emacs)

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Juanma Barranquero]

On Sat, Jun 9, 2012 at 1:30 PM, Eli Zaretskii <eliz@gnu.org> wrote:

> Is this slowdown expected?  Can it be fixed?

If it can not be fixed, that's one good reason to change the bootstrap
process on Windows.

    Juanma

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Christoph Scholtes]

On 6/9/2012 2:07 PM, Juanma Barranquero wrote:
> On Sat, Jun 9, 2012 at 1:30 PM, Eli Zaretskii <eliz@gnu.org> wrote:
>
>> Is this slowdown expected?  Can it be fixed?
>
> If it can not be fixed, that's one good reason to change the bootstrap
> process on Windows.

I had started to look into aligning the bootstrap process between Linux 
and Windows, but I didn't get very far. I also don't have very much time 
to spend on development right now so someone(TM) might beat me to it. ;)

What exactly did cause the slowdown?

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Stefan Monnier]

> The byte compiler seems to be a lot slower now, when run interpreted,
> compared with how it was a couple of weeks ago.  With the current
> trunk:

Before revno 108533, I wouldn't have been surprised, but after that I do
not know what could cause such a significant slowdown.

> Is this slowdown expected?  Can it be fixed?

It is expected that the byte-compiler is significantly slower when
interpreted, especially because of liberal use of macros and the
inefficient way macros are re-expanded when interpreted, but an 8-times
slowdown compared to the old interpreted code is definitely
not expected.

One potential source of slowness is the use of `pcase' in macroexp.el:
when byte-compiled, this is not a problem since it's all macroexpanded
away into reasonably efficient code.  But when interpreted, the `pcase'
macro might get re-expanded over and over, and it's a macro that's
costly to expand (because it has to work fairly hard in order to get
this reasonably efficient code).  pcase.el uses a hash-table to memoize
the recent expansions, but if for some reason this memoization fails and
the pcase macro gets re-expanded all the time, then an 8-fold slowdown
would not surprise me.


        Stefan

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Eli Zaretskii]

> From: Stefan Monnier <monnier@iro.umontreal.ca>
> Cc: 11657@debbugs.gnu.org
> Date: Sat, 09 Jun 2012 21:24:43 -0400
> 
> One potential source of slowness is the use of `pcase' in macroexp.el:
> when byte-compiled, this is not a problem since it's all macroexpanded
> away into reasonably efficient code.  But when interpreted, the `pcase'
> macro might get re-expanded over and over, and it's a macro that's
> costly to expand (because it has to work fairly hard in order to get
> this reasonably efficient code).  pcase.el uses a hash-table to memoize
> the recent expansions, but if for some reason this memoization fails and
> the pcase macro gets re-expanded all the time, then an 8-fold slowdown
> would not surprise me.

Is there any way I can help you look into this?

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Stefan Monnier]

>> One potential source of slowness is the use of `pcase' in macroexp.el:
>> when byte-compiled, this is not a problem since it's all macroexpanded
>> away into reasonably efficient code.  But when interpreted, the `pcase'
>> macro might get re-expanded over and over, and it's a macro that's
>> costly to expand (because it has to work fairly hard in order to get
>> this reasonably efficient code).  pcase.el uses a hash-table to memoize
>> the recent expansions, but if for some reason this memoization fails and
>> the pcase macro gets re-expanded all the time, then an 8-fold slowdown
>> would not surprise me.
> Is there any way I can help you look into this?

I suspect that the slowdown is linked to the stack increase, so if you
could show me the (Lisp) backtrace when it hits the 1500 mark, for
example, or better yet if we could compare the backtrace when it hits
1000 in the old code and in the new code.

Another would be to add some instrumentation code to the `pcase' macro,
to output a message everytime the cache misses.  E.g. use the patch below.


        Stefan


=== modified file 'lisp/emacs-lisp/pcase.el'
--- lisp/emacs-lisp/pcase.el	2012-06-09 03:14:44 +0000
+++ lisp/emacs-lisp/pcase.el	2012-06-10 14:47:34 +0000
@@ -215,8 +215,8 @@
   (and (symbolp upat) (not (memq upat pcase--dontcare-upats))))
 
 (defun pcase--expand (exp cases)
-  ;; (message "pid=%S (pcase--expand %S ...hash=%S)"
-  ;;          (emacs-pid) exp (sxhash cases))
+  (message "pid=%S (pcase--expand %S ...hash=%S)"
+           (emacs-pid) exp (sxhash cases))
   (let* ((defs (if (symbolp exp) '()
                  (let ((sym (make-symbol "x")))
                    (prog1 `((,sym ,exp)) (setq exp sym)))))

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Stefan Monnier]

> Another would be to add some instrumentation code to the `pcase' macro,
> to output a message everytime the cache misses.  E.g. use the patch below.

I tried that and found that the `pcase-let' macro was not memoized (it
goes through `pcase' but pcase's memoization fails in that case).
I added explicit memoization to pcase-let, which should
help significantly.

Please try it and tell me if it was the only source of slowdown.

BTW, regarding those problems, I'm experimenting with a change that
calls macroexpand-all directly from readevalloop, so as to avoid such
repeated macro-expansion.


        Stefan

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Eli Zaretskii]

> From: Stefan Monnier <monnier@iro.umontreal.ca>
> Cc: 11657@debbugs.gnu.org
> Date: Sun, 10 Jun 2012 21:10:07 -0400
> 
> > Another would be to add some instrumentation code to the `pcase' macro,
> > to output a message everytime the cache misses.  E.g. use the patch below.
> 
> I tried that and found that the `pcase-let' macro was not memoized (it
> goes through `pcase' but pcase's memoization fails in that case).
> I added explicit memoization to pcase-let, which should
> help significantly.
> 
> Please try it and tell me if it was the only source of slowdown.

Unfortunately, I see no improvement at all, with trunk revision
108559: I still get the same 16.5 sec compiling org.el.

Thanks.

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Stefan Monnier]

>> > Another would be to add some instrumentation code to the `pcase' macro,
>> > to output a message everytime the cache misses.  E.g. use the patch below.
>> I tried that and found that the `pcase-let' macro was not memoized (it
>> goes through `pcase' but pcase's memoization fails in that case).
>> I added explicit memoization to pcase-let, which should
>> help significantly.
>> Please try it and tell me if it was the only source of slowdown.
> Unfortunately, I see no improvement at all, with trunk revision
> 108559: I still get the same 16.5 sec compiling org.el.

I think I see another cause for slowdown: macroexp now ends up preloaded
in bootstrap-emacs, so byte-compiling it from COMPILE_FIRST is
ineffective (BTW, we can remove subr.el from makefile-w32.in's
COMPILE_FIRST, since it's useless there).


        Stefan

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Juanma Barranquero]

On Thu, Jun 14, 2012 at 9:09 PM, Stefan Monnier
<monnier@iro.umontreal.ca> wrote:

> (BTW, we can remove subr.el from makefile-w32.in's
> COMPILE_FIRST, since it's useless there).

Done in revno:108612.

BTW, why the differences between the makefile.in COMPILE_FIRST:

COMPILE_FIRST = \
        ...
	$(lisp)/emacs-lisp/autoload.elc

and the makefile.w32-in one?

COMPILE_FIRST = \
        ...
	$(lisp)/progmodes/cc-mode.el \
	$(lisp)/progmodes/cc-vars.el


    Juanma

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Stefan Monnier]

>> (BTW, we can remove subr.el from makefile-w32.in's
>> COMPILE_FIRST, since it's useless there).

> Done in revno:108612.

> BTW, why the differences between the makefile.in COMPILE_FIRST:

> COMPILE_FIRST = \
>         ...
> 	$(lisp)/emacs-lisp/autoload.elc

> and the makefile.w32-in one?

> COMPILE_FIRST = \
>         ...
> 	$(lisp)/progmodes/cc-mode.el \
> 	$(lisp)/progmodes/cc-vars.el

No idea.


        Stefan

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Eli Zaretskii]

> From: Juanma Barranquero <lekktu@gmail.com>
> Date: Fri, 15 Jun 2012 01:56:29 +0200
> Cc: Eli Zaretskii <eliz@gnu.org>, 11657@debbugs.gnu.org
> 
> On Thu, Jun 14, 2012 at 9:09 PM, Stefan Monnier
> <monnier@iro.umontreal.ca> wrote:
> 
> > (BTW, we can remove subr.el from makefile-w32.in's
> > COMPILE_FIRST, since it's useless there).
> 
> Done in revno:108612.

Thanks.

> BTW, why the differences between the makefile.in COMPILE_FIRST:
> 
> COMPILE_FIRST = \
>         ...
> 	$(lisp)/emacs-lisp/autoload.elc
> 
> and the makefile.w32-in one?
> 
> COMPILE_FIRST = \
>         ...
> 	$(lisp)/progmodes/cc-mode.el \
> 	$(lisp)/progmodes/cc-vars.el

See revno 36919, where Gerd Moellmann added them both to
lisp/Makefile.in and lisp/makefile.w32-in.

I have no idea whether what the comment says about bootstrap is still
true nowadays, since the bootstrap on Windows works differently.  You
can try removing those 2 files and see if that hurts anything.

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Juanma Barranquero]

On Fri, Jun 15, 2012 at 11:27 AM, Eli Zaretskii <eliz@gnu.org> wrote:

> I have no idea whether what the comment says about bootstrap is still
> true nowadays, since the bootstrap on Windows works differently.  You
> can try removing those 2 files and see if that hurts anything.

After synching lisp/makefile.w32-in with Stefan's changes in
revno:88864, emacs bootstraps just fine.

I haven't tried to evaluate any possible impact in byte-compilation
time, given its current state.

    Juanma


=== modified file 'lisp/makefile.w32-in'
--- lisp/makefile.w32-in	2012-06-14 23:53:41 +0000
+++ lisp/makefile.w32-in	2012-06-15 19:39:42 +0000
@@ -76,18 +76,14 @@
 BYTE_COMPILE_FLAGS = $(BIG_STACK_OPTS) $(BYTE_COMPILE_EXTRA_FLAGS)

 # Files to compile before others during a bootstrap.  This is done to
-# speed up the bootstrap process.  The CC files are compiled first
-# because CC mode tweaks the compilation process, and requiring
-# cc-mode when it is not compiled doesn't work during the
-# bootstrapping.
+# speed up the bootstrap process.

 COMPILE_FIRST = \
+	$(lisp)/emacs-lisp/bytecomp.el \
 	$(lisp)/emacs-lisp/byte-opt.el \
-	$(lisp)/emacs-lisp/bytecomp.el \
 	$(lisp)/emacs-lisp/macroexp.el \
 	$(lisp)/emacs-lisp/cconv.el \
-	$(lisp)/progmodes/cc-mode.el \
-	$(lisp)/progmodes/cc-vars.el
+	$(lisp)/emacs-lisp/autoload.el

 # The actual Emacs command run in the targets below.
 # The quotes around $(EMACS) are here because the user could type

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Eli Zaretskii]

> From: Juanma Barranquero <lekktu@gmail.com>
> Date: Fri, 15 Jun 2012 21:43:40 +0200
> Cc: monnier@iro.umontreal.ca, 11657@debbugs.gnu.org
> 
> On Fri, Jun 15, 2012 at 11:27 AM, Eli Zaretskii <eliz@gnu.org> wrote:
> 
> > I have no idea whether what the comment says about bootstrap is still
> > true nowadays, since the bootstrap on Windows works differently.  You
> > can try removing those 2 files and see if that hurts anything.
> 
> After synching lisp/makefile.w32-in with Stefan's changes in
> revno:88864, emacs bootstraps just fine.

Then I guess you can install this.  Thanks.

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Stefan Monnier]

> I think I see another cause for slowdown: macroexp now ends up preloaded
> in bootstrap-emacs, so byte-compiling it from COMPILE_FIRST is
> ineffective (BTW, we can remove subr.el from makefile-w32.in's
> COMPILE_FIRST, since it's useless there).

Do you still see the much slower compilation with bootstrap-emacs?
I guess you do, if so, please try the patch below and tell me if it
helps,


        Stefan


=== modified file 'lisp/loadup.el'
--- lisp/loadup.el	2012-06-13 13:18:59 +0000
+++ lisp/loadup.el	2012-06-20 16:23:57 +0000
@@ -252,6 +252,20 @@
 ;For other systems, you must edit ../src/Makefile.in.
 (load "site-load" t)
 
+;; src/boostrap-emacs is mostly used to compile .el files, so it needs
+;; macroexp, bytecomp, cconv, and byte-opt to be fast.  Generally this is done
+;; by compiling those files first, but this only makes a difference if those
+;; files are not preloaded.  As it so happens, macroexp.el tends to be
+;; accidentally preloaded in src/boostrap-emacs because cl.el and cl-macs.el
+;; require it.  So lets unload it here, if needed, to make sure the
+;; byte-compiled versions is used.
+(if (or (not (fboundp 'macroexpand-all))
+        (byte-code-function-p (symbol-function 'macroexpand-all)))
+    nil
+  (fmakunbound 'macroexpand-all)
+  (setq features (delq 'macroexp features))
+  (autoload 'macroexpand-all "macroexp"))
+
 ;; Determine which last version number to use
 ;; based on the executables that now exist.
 (if (and (or (equal (nth 3 command-line-args) "dump")

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Juanma Barranquero]

On Wed, Jun 20, 2012 at 6:33 PM, Stefan Monnier
<monnier@iro.umontreal.ca> wrote:

> I guess you do, if so, please try the patch below and tell me if it
> helps,

Full bootstrap

 - without your patch: 1:09:53
 - with your patch: 0:29:04

    Juanma

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Eli Zaretskii]

> From: Stefan Monnier <monnier@iro.umontreal.ca>
> Cc: 11657@debbugs.gnu.org
> Date: Wed, 20 Jun 2012 12:33:06 -0400
> 
> > I think I see another cause for slowdown: macroexp now ends up preloaded
> > in bootstrap-emacs, so byte-compiling it from COMPILE_FIRST is
> > ineffective (BTW, we can remove subr.el from makefile-w32.in's
> > COMPILE_FIRST, since it's useless there).
> 
> Do you still see the much slower compilation with bootstrap-emacs?
> I guess you do, if so, please try the patch below and tell me if it
> helps,

I see you already installed this.  With the current trunk, the byte
compiler in bootstrap-emacs returned to its previous speed,
i.e. compiling org.el takes about 2.2 sec.

Thanks, I think this bug report can be closed now.

bug#11657: 24.1.50; Byte compiler is a lot slower now, when run interpreted

[Glenn Morris]

Eli Zaretskii wrote:

> Thanks, I think this bug report can be closed now.

As a general comment, whever you find yourself saying that, I suggest
you just do it instead (particularly when you are the OP, like now).
It's easy to undo; and otherwise I think things are likely to get left
open when they needn't be.