Opened 4 years ago

Last modified 4 years ago

#1334 new defect

it is slow to define macros with huge numbers of args

Reported by: rme Owned by:
Priority: trivial Milestone:
Component: Compiler Version: trunk
Keywords: Cc: jared.c.davis@…

Description

[from a client]

An external person who was using our code managed to run into a performance problem. They were doing something really strange that ultimately resulted in the creation of a macro with thousands of arguments.

We told them not to do that, but I thought I'd at least mention that it seems the cost of introducing a macro really grows very quickly in the number of arguments. Below is some test code you can try to quickly see the problem.

(defun make-variable-list (n)
  (if (eql n 0)
    nil
    (cons (intern (format nil "X~s" n) "CL-USER")
	  (make-variable-list (- n 1)))))

(defun make-macro-fn (n)
  `(defmacro ,(intern (format nil "MY-MACRO-~s" n) "CL-USER")
       ,(make-variable-list n)
     (cons 'list (list . ,(make-variable-list n)))))

(defmacro make-macro (n)
  "Introduce MY-MACRO-N which just LISTs its N arguments."
  (make-macro-fn n))
(make-macro 3)      ;; Example: introduces MY-MACRO-3.
(my-macro-3 1 2 3)  ;; Example: returns (1 2 3).

;; Time introducing macros with increasing arguments...
(loop for n in '(1 2 4 8 16 32 64 128 256 512 1024 2048) do
      (let ((start (get-internal-real-time)))
	(eval `(make-macro ,n))
	(format t "For n=~s, took ~s seconds.~%"
		n
		(/ (coerce (- (get-internal-real-time) start) 'float)
		   internal-time-units-per-second))))

Results from CCL 1.12-dev-r16646M-trunk (LinuxX8664)

   For n=1, took 3.65E-4 seconds.
   For n=2, took 4.1E-4 seconds.
   For n=4, took 5.52E-4 seconds.
   For n=8, took 8.78E-4 seconds.
   For n=16, took 0.001554 seconds.
   For n=32, took 0.003434 seconds.
   For n=64, took 0.009028 seconds.
   For n=128, took 0.029557 seconds.
   For n=256, took 0.115807 seconds.
   For n=512, took 0.615766 seconds.
   For n=1024, took 3.532898 seconds.
   For n=2048, took 21.192232 seconds.

Results from SBCL 1.2.12.40-1cac435 (also bad!)

   For n=1, took 0.001 seconds.
   For n=2, took 0.0 seconds.
   For n=4, took 0.001 seconds.
   For n=8, took 0.001 seconds.
   For n=16, took 0.002 seconds.
   For n=32, took 0.005 seconds.
   For n=64, took 0.022 seconds.
   For n=128, took 0.154 seconds.
   For n=256, took 1.065 seconds.
   For n=512, took 11.156 seconds.
   Heap exhausted during garbage collection: 128 bytes available, 144
requested. [...]
      Total bytes allocated    = 1070771168
      Dynamic-space-size bytes = 1073741824
   [...]
   fatal error encountered in SBCL pid 4814(tid 46912496193760):
   Heap exhausted, game over.

Change History (2)

comment:1 Changed 4 years ago by gb

How much time is spent defining and expanding the macro, and how much is spent using EVAL on the expansion ?

e.g.

.... (let ((form (time `(make-macro ,n)))

(time (eval form))

....

If the first use of TIME shows that a lot of time is spent defining and expanding the macro, I would guess that that is because of time spent in (FORMAT NIL ...) and INTERN.

If the more expensive case is rhe one involving EVAL, that tells us that EVAL can be very slow.

If the original code didn't use EVAL, my fixating on it may be a distraction.

It is not clear to me that this says much about macros and how many arguments they take.

comment:2 Changed 4 years ago by jared

  • Cc jared.c.davis@… added

Hi,

Here's an alternate version that doesn't use eval and still seems to have the problem.

(defun make-variable-list (n)
  (if (eql n 0)
    nil
    (cons (intern (format nil "X~s" n) "CL-USER")
	  (make-variable-list (- n 1)))))

(defun make-macro-fn (n)
  `(defmacro ,(intern (format nil "MY-MACRO-~s" n) "CL-USER")
       ,(make-variable-list n)
     (cons 'list (list . ,(make-variable-list n)))))

(defmacro make-macro (n)
  "Introduce MY-MACRO-N which just LISTs its N arguments."
  (make-macro-fn n))

(defmacro run-test (n)
  `(time (make-macro ,n)))

(run-test 1)
(run-test 2)
(run-test 4)
(run-test 8)
(run-test 16)
(run-test 32)
(run-test 64)
(run-test 128)
(run-test 256)
(run-test 512)
(run-test 1024)
(run-test 2048)

NOTE: The times reported (time ...) seem to be completely wrong. If you run this and just read the timing reports but don't pay any attention to how long is actually passing, you might mistakenly believe that each of the above takes 0.000015 seconds.

But if you change run-test to the following, you'll get timings that seem to make much more sense:

(defparameter *now* nil)

(defmacro run-test (n)
  `(progn (setq *now* (get-internal-real-time))
          (make-macro ,n)
          (format t "For n=~s, took ~s seconds.~%"
                  ,n
                  (/ (coerce (- (get-internal-real-time) *now*) 'float)
                     internal-time-units-per-second))))

Here are the results I get, which seem to show the same slowdown:

? For n=1, took 3.87E-4 seconds.
? For n=2, took 4.31E-4 seconds.
? For n=4, took 5.93E-4 seconds.
? For n=8, took 9.02E-4 seconds.
? For n=16, took 0.00165 seconds.
? For n=32, took 0.003681 seconds.
? For n=64, took 0.009825 seconds.
? For n=128, took 0.032365 seconds.
? For n=256, took 0.125797 seconds.
? For n=512, took 0.670076 seconds.
? For n=1024, took 3.737392 seconds.
? For n=2048, took 21.848654 seconds.

Thanks for looking into this.

Jared

Note: See TracTickets for help on using tickets.