byte-compiler very slow

byte-compiler very slow

[David Ponce]

Hi All,

Since about a month, I noticed an important slow down of the
CVS version of the byte-compiler.  This is particularly annoying when
byte-compiling large files or doing batch compilation of a bunch of
files, or bootstrapping Emacs ;-)

Other people noticed that too?

To be sure I did some empiric measurements of byte-compilation time
of some files, both with Emacs 21.2.1 byte-compiler and latest CVS
one (2.105).  Here are some results I got on my IBM 390E laptop on
NT4:

  +--------------------+------------+-----------+
  | File               | 21.2.1     | 21.3.50.1 |
  +--------------------+------------+-----------+
  | bytecomp.el (1)    | 1.593S     | 18.297S   |
  | edebug.el (1)      | 1.462S     | 10.775S   |
  | wisent.java.el (2) | 5.979S     | 39.677S   |
  +--------------------+------------+-----------+
  (1) Latest CVS version
  (2) Java LALR automaton & related code (part of the Semantic
      toolkit).

A first quick comparison between the 21.2.1 and latest CVS versions of
bytecomp.el codes showed me that the main addition that could impact
performance could be related to the new (nice) feature that reports
symbol positions on byte-compiler messages.

Could it be possible to improve that code?  Or perhaps optionally
disable reporting of symbol positions, at least when running in batch
mode?

Sincerely,
David


In GNU Emacs 21.3.50.1 (i386-mingw-nt4.0.1381)
 of 2002-07-20 on EBAT311
configured using `configure --with-gcc (2.95)'

Important settings:
  value of $LC_ALL: nil
  value of $LC_COLLATE: nil
  value of $LC_CTYPE: nil
  value of $LC_MESSAGES: nil
  value of $LC_MONETARY: nil
  value of $LC_NUMERIC: nil
  value of $LC_TIME: nil
  value of $LANG: ENU
  locale-coding-system: iso-latin-1
  default-enable-multibyte-characters: t

Re: byte-compiler very slow

[David Ponce]

Hi All,

[...]
 > A first quick comparison between the 21.2.1 and latest CVS versions
 > of bytecomp.el codes showed me that the main addition that could
 > impact performance could be related to the new (nice) feature that
 > reports symbol positions on byte-compiler messages.
[...]

I did more performance measurements of the byte-compiler with a
version where I disabled handling of symbol positions, and not noticed
a sensible speed up of byte-compilation.  So the slow down, compared
to 21.2.1 version, seems to be caused by another change.

I must admit that I don't see what actually causes a such performance
degradation.

Maybe someone else has an idea?

Hope it helps.

Sincerely,
David

Re: byte-compiler very slow

[Richard Stallman]

    A first quick comparison between the 21.2.1 and latest CVS versions of
    bytecomp.el codes showed me that the main addition that could impact
    performance could be related to the new (nice) feature that reports
    symbol positions on byte-compiler messages.

I think this is an extremely nice feature.  It is worth some slowdown,
byt 5x or 9x seems a bit much.  It would be useful to do some
profiling on this.  Does someeone want to do that?

I have a feeling Colin Walters, who added that feature, may be on
vacation.  Colin, if you are there, could you please speak up?

A simple optimization idea occurs to me.  The byte compiler could
start processing a sexp in the old mode with the location tracking
feature turned off.  If it encounters any sort of warning or error, it
could abort processing of that sexp and restart with the location
tracking feature turned on.  This would give the same results but
all non-erroneous sexps would be processed faster.

The only case where this causes a problem would be when macros do very
weird things, such as if they their behavior depends on how many times
the macro is expanded.  Perhaps it is an adequate solution to that
problem to say "Don't do that".

Re: byte-compiler very slow

[Colin Walters]

On Sun, 2002-07-21 at 16:15, Richard Stallman wrote:

> I think this is an extremely nice feature.  It is worth some slowdown,
> byt 5x or 9x seems a bit much.  It would be useful to do some
> profiling on this.  Does someeone want to do that?
> 
> I have a feeling Colin Walters, who added that feature, may be on
> vacation.  Colin, if you are there, could you please speak up?

Sorry, yes, semi-vacation; I've been trying to complete another free
software project.

> A simple optimization idea occurs to me.  The byte compiler could
> start processing a sexp in the old mode with the location tracking
> feature turned off.  If it encounters any sort of warning or error, it
> could abort processing of that sexp and restart with the location
> tracking feature turned on.  This would give the same results but
> all non-erroneous sexps would be processed faster.

That would be a good way to handle it, but unfortunately in the current
byte compiler implementation all sorts of side-effects happen while
processing a sexp.  It would be pretty tricky to unwind all of those.

I think for the short term, we could make batch-byte-compile set a flag
which reverts to the previous behavior of just printing line numbers. 
How does that sound?

> The only case where this causes a problem would be when macros do very
> weird things, such as if they their behavior depends on how many times
> the macro is expanded.  Perhaps it is an adequate solution to that
> problem to say "Don't do that".

There are already no guarantees on how many times a macro can be
expanded, or exactly when it will be expanded, so I don't see a problem
with this.

Re: byte-compiler very slow

[Richard Stallman]

    I think for the short term, we could make batch-byte-compile set a flag
    which reverts to the previous behavior of just printing line numbers. 

The previous behavior printed *incorrect* line numbers; going back
there does not seem very good.  I think we should make this work
better.

Someone said that turning this feature off does not bring back the old
speed.  I wonder if turning it off really turns off the whole
mechanism.  Did anyone check what the code says?

Treating the code as a black box is unlikely to solve this.  That's a
futile approach to any bug, almost a waste of time.  What we need is
some real debugging.  Would someone like to study the actual changes
and what they do that might cause a slowdown?  Would someone like to
profile the new version and see where this time is spent?

Re: byte-compiler very slow

[David Ponce]

Hi All,

I think I found the cause of the byte-compiler slow down.  I profiled
the byte-compiler and finally found that most of the byte-compilation
time was spent in the function `symbol-file' called from
`byte-compile-cl-warn'.  In fact I found that the time spent in
`symbol-file' is proportional to the size of `load-history'.

Here is a summary profiling result I got when byte-compiling edebug.el
in my normal working environment where `load-history' is quite big:

Function Name            Call Count  Elapsed Time  Average Time
=======================  ==========  ============  ============
emacs-lisp-byte-compile  1           12.077        12.077
symbol-file              3590        9.0729999999  0.0025272980

That clearly shows that 75% of compilation time is spent in
`symbol-file'!

Here is the result I got just after `emacs -q --no-site-file' when
`load-history' should be at minimal size:

Function Name            Call Count  Elapsed Time  Average Time
=======================  ==========  ============  ============
emacs-lisp-byte-compile  1           3.235         3.235
symbol-file              3589        0.9410000000  0.0002621900

In that case only 29% of time is spent in `symbol-file'!

To confirm these results I hacked a version of bytecomp.el where I
replaced `byte-compile-cl-warn' with the following:

(defsubst byte-compile-cl-warn (form)
  "Warn if FORM is a call of a function from the CL package."
  form)

And magically, the byte-compiler recovered its speed :-)

Hope this will help.

Sincerely,
David

Re: byte-compiler very slow

[Richard Stallman]

Thanks for tracking down the slowness in byte-compile-cl-warn.  With
that information it was not hard for me to speed up the test.  Please
try this.


*** bytecomp.el.~2.106.~	Sat Jul 20 18:01:19 2002
--- bytecomp.el	Tue Jul 23 21:47:01 2002
***************
*** 957,962 ****
--- 957,963 ----
  ;; Also log the current function and file if not already done.
  (defun byte-compile-log-warning (string &optional fill level)
    (let ((warning-prefix-function 'byte-compile-warning-prefix)
+ 	(warning-group-format "")
  	(warning-fill-prefix (if fill "    ")))
      (display-warning 'bytecomp string level "*Compile-Log*")))
  
***************
*** 1201,1223 ****
  		    (delq calls byte-compile-unresolved-functions)))))
        )))
  
  (defun byte-compile-cl-warn (form)
    "Warn if FORM is a call of a function from the CL package."
!   (let* ((func (car-safe form))
! 	 (library
! 	  (if func
! 	      (cond ((eq (car-safe func) 'autoload)
! 		     (nth 1 func))
! 		    ((symbol-file func))))))
!     (if (and library
! 	     (string-match "^cl\\>" library)
  	     ;; Aliases which won't have been expended at this point.
  	     ;; These aren't all aliases of subrs, so not trivial to
  	     ;; avoid hardwiring the list.
  	     (not (memq func
  			'(cl-block-wrapper cl-block-throw
  			  multiple-value-call nth-value
! 			  copy-seq first second rest endp cl-member))))
  	(byte-compile-warn "Function `%s' from cl package called at runtime"
  			   func)))
    form)
--- 1202,1240 ----
  		    (delq calls byte-compile-unresolved-functions)))))
        )))
  
+ (defvar byte-compile-cl-functions nil
+   "List of functions defined in CL.")
+ 
+ (defun byte-compile-find-cl-functions ()
+   (unless byte-compile-cl-functions
+     (dolist (elt load-history)
+       (when (string-match "^cl\\>" (car elt))
+ 	(setq byte-compile-cl-functions
+ 	      (append byte-compile-cl-functions
+ 		      (cdr elt)))))
+     (let ((tail byte-compile-cl-functions))
+       (while tail
+ 	(if (and (consp (car tail))
+ 		 (eq (car (car tail)) 'autoload))
+ 	    (setcar tail (cdr (car tail))))
+ 	(setq tail (cdr tail))))))
+ 
  (defun byte-compile-cl-warn (form)
    "Warn if FORM is a call of a function from the CL package."
!   (let ((func (car-safe form)))
!     (if (and byte-compile-cl-functions
! 	     (memq func byte-compile-cl-functions)
  	     ;; Aliases which won't have been expended at this point.
  	     ;; These aren't all aliases of subrs, so not trivial to
  	     ;; avoid hardwiring the list.
  	     (not (memq func
  			'(cl-block-wrapper cl-block-throw
  			  multiple-value-call nth-value
! 			  copy-seq first second rest endp cl-member
! 			  ;; This is sometimes defined in CL
! 			  ;; but that redefines a standard function,
! 			  ;; so don't warn about it.
! 			  macroexpand))))
  	(byte-compile-warn "Function `%s' from cl package called at runtime"
  			   func)))
    form)
***************
*** 1317,1322 ****
--- 1334,1340 ----
    `(let (warning-series)
       ;; Log the file name.  Record position of that text.
       (setq warning-series (byte-compile-log-file))
+      (byte-compile-find-cl-functions)
       (let ((--displaying-byte-compile-warnings-fn (lambda ()
  						    ,@body)))
         (if byte-compile-debug

Re: byte-compiler very slow

[David Ponce]

Hi Richard,

 > Thanks for tracking down the slowness in byte-compile-cl-warn.  With
 > that information it was not hard for me to speed up the test.
 > Please try this.

Your patch works like a charm!  Here is the new profiling result I got
when byte-compiling edebug.el:

emacs-lisp-byte-compile  1           3.024         3.024
byte-compile-cl-warn     3590        0.581         0.0001618384

Compared to result with previous version:

emacs-lisp-byte-compile  1           11.978        11.978
byte-compile-cl-warn     3590        9.1439999999  0.0025470752

Did you receive my patch to improve the performance of
`byte-compile-set-symbol-position'?

Thanks!
David

Re: byte-compiler very slow

[Richard Stallman]

    Did you receive my patch to improve the performance of
    `byte-compile-set-symbol-position'?

Yes, and I installed it.  Thanks.

Re: byte-compiler very slow (cont.)

[David Ponce]

Hi,

I continued to work on byte-compiler slow down and also found that,
in certain cases, the function `byte-compile-set-symbol-position' can
sensibly impact the performance.

A such example is wisent-java.el (the Java LALR automaton part of
Semantic toolkit) which contains an array of 293 very short lambda
forms (the semantic actions to apply when reducing rules).  This array
is byte-compiled by the function `wisent-semantic-actions' that, in
fact, calls `byte-compile' on each array element.  After profiling I
found the following (I disabled checking of 'cl-functions warnings,
see my previous post):

Function Name                    Call Count  Elapsed Time  Average Time
=======================          ==========  ============  ============
wisent-semantic-actions          1           23.324        23.324
byte-compile-set-symbol-position 17749       19.979        0.001126

Showing that the time spent in `byte-compile-set-symbol-position' is
not negligible!

I significantly improved that result with the following patch:

*** bytecomp.el.ori    Sun Jul 21 01:14:04 2002
--- bytecomp.el    Tue Jul 23 15:02:35 2002
***************
*** 848,854 ****
    "Last known character position in the input.")
 
  ;; copied from gnus-util.el
! (defun byte-compile-delete-first (elt list)
    (if (eq (car list) elt)
        (cdr list)
      (let ((total list))
--- 848,854 ----
    "Last known character position in the input.")
 
  ;; copied from gnus-util.el
! (defsubst byte-compile-delete-first (elt list)
    (if (eq (car list) elt)
        (cdr list)
      (let ((total list))
***************
*** 872,889 ****
  ;; gross hack?  And the answer, of course, would be yes.
  (defun byte-compile-set-symbol-position (sym &optional allow-previous)
    (when byte-compile-read-position
!     (let ((last nil))
        (while (progn
!            (setq last byte-compile-last-position)
!            (let* ((entry (assq sym read-symbol-positions-list))
!               (cur (cdr entry)))
!          (setq byte-compile-last-position
!                (if cur
!                (+ byte-compile-read-position cur)
!              last))
!          (setq
!           read-symbol-positions-list
!           (byte-compile-delete-first entry read-symbol-positions-list)))
             (or (and allow-previous (not (= last 
byte-compile-last-position)))
             (> last byte-compile-last-position)))))))
 
--- 872,887 ----
  ;; gross hack?  And the answer, of course, would be yes.
  (defun byte-compile-set-symbol-position (sym &optional allow-previous)
    (when byte-compile-read-position
!     (let (last entry)
        (while (progn
!            (setq last byte-compile-last-position
!              entry (assq sym read-symbol-positions-list))
!            (when entry
!            (setq byte-compile-last-position
!              (+ byte-compile-read-position (cdr entry))
!              read-symbol-positions-list
!              (byte-compile-delete-first
!               entry read-symbol-positions-list)))
             (or (and allow-previous (not (= last 
byte-compile-last-position)))
             (> last byte-compile-last-position)))))))
 
With the above patch applied, profiling gave me:

Function Name                    Call Count  Elapsed Time  Average Time
=======================          ==========  ============  ============
wisent-semantic-actions          1           4.787         4.787
byte-compile-set-symbol-position 17749       1.371         7.772e-005

What do you think?

Sincerely,
David