source-path recording wastes time on quoted lists

[Matt Kaufmann]

The test case below shows that EVAL of a call of TIME can be very
slow. This log is from an Opteron running 32-bit linux and SBCL
1.0.43. I had similar results on a Mac (Darwin) running SBCL 1.0.29.

The log shows a slowdown whether we call TEST-TIME or just use its
body. However, evaluation of (print (eq (eval `(time big)) big)) is
fast -- it's something about `(time (quote ,big)) passed to EVAL that
is causing the problem.

By the way, I tried this test with others Lisps on 32-bit Linux (where
I compile functions explicitly for CMUCL, GCL, and Allegro CL). I'm
not seeing this problem with CCL, or (where I'm compiling functions)
with GCL or Allegro CL. I do see it with CMUCL, where I get lots of
GC messages.

lhug-8:~> /p/bin/sbcl-1.0.43
This is SBCL 1.0.43, an implementation of ANSI Common Lisp.
More information about SBCL is available at <http://www.sbcl.org/>.

SBCL is free software, provided as is, with absolutely no warranty.
It is mostly in the public domain; some portions are provided under
BSD-style licenses. See the CREDITS and COPYING files in the
distribution for more information.
* (declaim (optimize (compilation-speed 0) (speed 3) (space 0) (safety 0)))

* (defun make-tree (n acc)
    (cond ((zerop n) acc)
   (t (make-tree (1- n) (cons acc acc)))))

MAKE-TREE
* (defconstant big (make-tree 10000 nil))

BIG
* (defun test-time () (print (eq (eval `(time (quote ,big))) big)))

TEST-TIME
* (let (old new)
    (setq old (get-internal-real-time))
    (test-time)
    (setq new (get-internal-real-time))
    (/ (- new old) (* 1.0 internal-time-units-per-second)))

Evaluation took:
  0.000 seconds of real time
  0.000000 seconds of total run time (0.000000 user, 0.000000 system)
  100.00% CPU
  4,529 processor cycles
  0 bytes consed

T
4.765
* (let (old new)
    (setq old (get-internal-real-time))
    (print (eq (eval `(time (quote ,big))) big))
    (setq new (get-internal-real-time))
    (/ (- new old) (* 1.0 internal-time-units-per-second)))

Evaluation took:
  0.000 seconds of real time
  0.000000 seconds of total run time (0.000000 user, 0.000000 system)
  100.00% CPU
  4,092 processor cycles
  0 bytes consed

T
4.725
* (defun test-no-time () (print (eq (eval `(quote ,big)) big)))

TEST-NO-TIME
* (let (old new)
    (setq old (get-internal-real-time))
    (test-no-time)
    (setq new (get-internal-real-time))
    (/ (- new old) (* 1.0 internal-time-units-per-second)))

T
0.0
* (let (old new)
    (setq old (get-internal-real-time))
    (print (eq (eval `(quote ,big)) big))
    (setq new (get-internal-real-time))
    (/ (- new old) (* 1.0 internal-time-units-per-second)))

T
0.0
*

.....

Additional info requested:

lhug-8:~> uname -a
Linux lhug-8.cs.utexas.edu 2.6.24.6.desktop11.28.75 #1 SMP Fri Aug 20 13:00:30 CDT 2010 i686 GNU/Linux
lhug-8:~> /p/bin/sbcl-1.0.43 --version
SBCL 1.0.43
lhug-8:~> /p/bin/sbcl-1.0.43
This is SBCL 1.0.43, an implementation of ANSI Common Lisp.
More information about SBCL is available at <http://www.sbcl.org/>.

SBCL is free software, provided as is, with absolutely no warranty.
It is mostly in the public domain; some portions are provided under
BSD-style licenses. See the CREDITS and COPYING files in the
distribution for more information.
* *features*

(:ANSI-CL :COMMON-LISP :SBCL :SB-DOC :SB-TEST :SB-LDB :SB-PACKAGE-LOCKS
 :SB-UNICODE :SB-EVAL :SB-SOURCE-LOCATIONS :IEEE-FLOATING-POINT :X86 :UNIX :ELF
 :LINUX :SB-THREAD :LARGEFILE :GENCGC :STACK-GROWS-DOWNWARD-NOT-UPWARD
 :C-STACK-IS-CONTROL-STACK :COMPARE-AND-SWAP-VOPS :UNWIND-TO-FRAME-AND-CALL-VOP
 :RAW-INSTANCE-INIT-VOPS :STACK-ALLOCATABLE-CLOSURES :STACK-ALLOCATABLE-VECTORS
 :STACK-ALLOCATABLE-LISTS :STACK-ALLOCATABLE-FIXED-OBJECTS :ALIEN-CALLBACKS
 :CYCLE-COUNTER :INLINE-CONSTANTS :MEMORY-BARRIER-VOPS :LINKAGE-TABLE
 :OS-PROVIDES-DLOPEN :OS-PROVIDES-DLADDR :OS-PROVIDES-PUTWC
 :OS-PROVIDES-SUSECONDS-T :OS-PROVIDES-GETPROTOBY-R :OS-PROVIDES-POLL)
*

[Matt Kaufmann (kaufmann)]

Sorry; this bug isn't only about TIME after all. It appears to be about a
slowdown in EVAL when there are LET-bindings in the form, as is
illustrated by the log just below (both for lexical and special
variables, as long as at least one variable is being bound). The
platform is as before: 32-bit Linux running SBCL 1.0.43. Again, CMUCL
shows the same slowdown; but GCL, Allegro CL, and CCL do not.

lhug-8:~> /p/bin/sbcl-1.0.43
This is SBCL 1.0.43, an implementation of ANSI Common Lisp.
More information about SBCL is available at <http://www.sbcl.org/>.

SBCL is free software, provided as is, with absolutely no warranty.
It is mostly in the public domain; some portions are provided under
BSD-style licenses. See the CREDITS and COPYING files in the
distribution for more information.
* (declaim (optimize (compilation-speed 0) (speed 3) (space 0) (safety 0)))

* (defun make-tree (n acc)
    (cond ((zerop n) acc)
   (t (make-tree (1- n) (cons acc acc)))))

MAKE-TREE
* (defconstant big (make-tree 10000 nil))

BIG
* (defun test ()
    (print (eq (eval `(let ((x 17)) (cdr (cons x (quote ,BIG)))))
        big)))

TEST
* (let (old new)
    (setq old (get-internal-real-time))
    (test)
    (setq new (get-internal-real-time))
    (/ (- new old) (* 1.0 internal-time-units-per-second)))

T
4.762
* (defvar *my-special* nil)

*MY-SPECIAL*
* (defun test2 ()
    (print (eq (eval `(let ((*my-special* 17)) (quote ,BIG)))
        big)))

TEST2
* (let (old new)
    (setq old (get-internal-real-time))
    (test2)
    (setq new (get-internal-real-time))
    (/ (- new old) (* 1.0 internal-time-units-per-second)))

T
4.764
* (defun test-fast ()
    (print (eq (eval `(quote ,BIG))
        big)))

TEST-FAST
* (let (old new)
    (setq old (get-internal-real-time))
    (test-fast)
    (setq new (get-internal-real-time))
    (/ (- new old) (* 1.0 internal-time-units-per-second)))

T
0.0
* (defun test3 ()
    (print (eq (eval `(let ((x 17)) (declare (ignore x)) (quote ,BIG)))
        big)))

TEST3
* (let (old new)
    (setq old (get-internal-real-time))
    (test3)
    (setq new (get-internal-real-time))
    (/ (- new old) (* 1.0 internal-time-units-per-second)))

T
4.751
* (defun test-fast2 ()
    (print (eq (eval `(let () (quote ,BIG)))
        big)))

TEST-FAST2
* (let (old new)
    (setq old (get-internal-real-time))
    (test-fast2)
    (setq new (get-internal-real-time))
    (/ (- new old) (* 1.0 internal-time-units-per-second)))

T
0.0
*

[Paul Khuong (pvk)]

There are two evaluators in SBCL (the situation is similar for CMUCL). The default evaluator compiles everything but the most trivial expression to native code, before executing it. You can switch to a regular interpreter by setting *evaluator-mode* to :interpret. Using the interpreter should have a consistently average performance.

Does that address your issue?

[Matt Kaufmann (kaufmann)]

Thank you; that indeed does solve the problem. Sorry I missed that in
the manual (I now see it mentioned in Section 4.6).

I'm still a bit surprised at the performance compared to CCL, which
also does compilation by default (though perhaps not for EVAL; I don't
know). I wonder if it might be good if EVAL were to bind
*evaluator-mode* to :interpret.

The rest of this comment is just FYI:

I've found a workaround, which I'll probably use so that my code works
in CMUCL as well and also avoids the need for #+sbcl -- unless someone
cares to suggest a workaround for CMUCL (I didn't find any occurrences
of "interpreter" in its user's manual, or using (apropos "EVAL")).
FYI, my workaround is to bind special variables to large objects; the
following illustrates the idea applied to the simplified first example
in the bug report.

lhug-8:~> /p/bin/sbcl-1.0.43
This is SBCL 1.0.43, an implementation of ANSI Common Lisp.
More information about SBCL is available at <http://www.sbcl.org/>.

SBCL is free software, provided as is, with absolutely no warranty.
It is mostly in the public domain; some portions are provided under
BSD-style licenses. See the CREDITS and COPYING files in the
distribution for more information.
* (declaim (optimize (compilation-speed 0) (speed 3) (space 0) (safety 0)))

* (defun make-tree (n acc)
    (cond ((zerop n) acc)
   (t (make-tree (1- n) (cons acc acc)))))

MAKE-TREE
* (defconstant big (make-tree 10000 nil))

BIG
* (defun test ()
    (print (eq (eval `(let ((x 17)) (cdr (cons x (quote ,BIG)))))
        big)))

TEST
* (let (old new)
    (setq old (get-internal-real-time))
    (test)
    (setq new (get-internal-real-time))
    (/ (- new old) (* 1.0 internal-time-units-per-second)))

T
4.762
* (defvar *my-special* nil)

*MY-SPECIAL*
* (defun test2 ()
    (print (eq (eval `(let ((*my-special* 17)) (quote ,BIG)))
        big)))

TEST2
* (let (old new)
    (setq old (get-internal-real-time))
    (test2)
    (setq new (get-internal-real-time))
    (/ (- new old) (* 1.0 internal-time-units-per-second)))

T
4.764
* (defun test-fast ()
    (print (eq (eval `(quote ,BIG))
        big)))

TEST-FAST
* (let (old new)
    (setq old (get-internal-real-time))
    (test-fast)
    (setq new (get-internal-real-time))
    (/ (- new old) (* 1.0 internal-time-units-per-second)))

T
0.0
* (defun test3 ()
    (print (eq (eval `(let ((x 17)) (declare (ignore x)) (quote ,BIG)))
        big)))

TEST3
* (let (old new)
    (setq old (get-internal-real-time))
    (test3)
    (setq new (get-internal-real-time))
    (/ (- new old) (* 1.0 internal-time-units-per-second)))

T
4.751
* (defun test-fast2 ()
    (print (eq (eval `(let () (quote ,BIG)))
        big)))

TEST-FAST2
* (let (old new)
    (setq old (get-internal-real-time))
    (test-fast2)
    (setq new (get-internal-real-time))
    (/ (- new old) (* 1.0 internal-time-units-per-second)))

T
0.0
*

[Nikodemus Siivola (nikodemus)]

IMO, what needs to happen to close this bugs is to make sure *INTERPRETER-MODE* is documented properly, and that those docs are findable.

I also filed a potential evaluator improvement that touches on this as bug 654412.

[Nikodemus Siivola (nikodemus)]

Huh, didn't notice how terrible the compiler performance is here at first.

The issue is source-path recording spending ages in the big list, which is pretty pointless. The point re. documentation stands, but the compiler performance here needs to be fixed.

Just disabling the source path recording takes time from

Evaluation took:
  3.199 seconds of real time
  3.140248 seconds of total run time (3.044901 user, 0.095347 system)
  [ Run times consist of 0.275 seconds GC time, and 2.866 seconds non-GC time. ]
  98.16% CPU
  1 form interpreted
  1 lambda converted
  8,298,004,910 processor cycles
  802,662,912 bytes consed

to

Evaluation took:
  0.001 seconds of real time
  0.001000 seconds of total run time (0.000885 user, 0.000115 system)
  100.00% CPU
  1 form interpreted
  1 lambda converted
  2,582,762 processor cycles
  84,656 bytes consed

but a smarter fix is coming.

[Nikodemus Siivola (nikodemus)]

Fixed in 1.0.43.19.

[Nikodemus Siivola (nikodemus)]

Test needs fixing, still:

[18:31] <gnooth> Failure: compiler.pure.lisp / BUG-654289
[18:31] <gnooth> if I change 10 to 20 it passes; maybe the test is assuming too fast of a machine

[Nikodemus Siivola (nikodemus)]

Test made less CPU-speed sensitive in 1.0.43.53.