Why does calling code as a function take longer than calling it directly in Clozure Common lisp?

Question

I have around 900000 RECORDS:

(defparameter RECORDS 
  '((293847 "john menk" "john.menk@example.com" 0123456789 2300 2760 "CHEQUE" 012345 "menk freeway" "high rose")
    (244841 "january agami" "j.a@example.com" 0123456789 2300 2760 "CHEQUE" 012345 "ishikawa street" "fremont apartments")
    ...))

(These are read from a file. The above code is provided only as an example. It helps show the internal structure of this data.)

For quick prototyping I use aliased names for selectors:

(defmacro alias (new-name existing-name)

  "Alias NEW-NAME to EXISTING-NAME. EXISTING-NAME has to be a function."

  `(setf (fdefinition ',new-name) #',existing-name))

(progn 
  (alias account-number first)
  (alias full-name second)
  (alias email third)
  (alias mobile fourth)
  (alias average-paid fifth)
  (alias highest-paid sixth)
  (alias usual-payment-mode seventh)
  (alias pincode eighth)
  (alias road ninth)
  (alias building tenth))

---

Now I run:

(time (loop for field in '(full-name email) 
        append (loop for record in RECORDS
                 when (cl-ppcre:scan ".*?january.*?agami.*?" 
                                     (funcall (symbol-function field) record))
                 collect record)))

The repl outputs:

...
took 1,714 milliseconds (1.714 seconds) to run.
During that period, and with 4 available CPU cores,
     1,698 milliseconds (1.698 seconds) were spent in user mode
         9 milliseconds (0.009 seconds) were spent in system mode
 40 bytes of memory allocated.
...

---

Define a function doing the same thing:

(defun searchx (regex &rest fields) 
  (loop for field in fields 
    append (loop for record in RECORDS
             when (cl-ppcre:scan regex (funcall (symbol-function field) record))
             collect record)))

And then call it:

(time (searchx ".*?january.*?agami.*?" 'full-name 'email))

The output:

...
took 123,389 milliseconds (123.389 seconds) to run.
         992 milliseconds (  0.992 seconds, 0.80%) of which was spent in GC.
During that period, and with 4 available CPU cores,
     118,732 milliseconds (118.732 seconds) were spent in user mode
       4,569 milliseconds (  4.569 seconds) were spent in system mode
 2,970,867,648 bytes of memory allocated.
 501 minor page faults, 0 major page faults, 0 swaps.
...

It's almost 70 times slower ?!!

I thought maybe it's a computer specific issue. So I ran the same code on two different machines. A macbook air, and a macbook pro. The individual timings vary, but the behaviour is consistent. Calling it as a function takes much longer than calling it directly on both machines. Surely the overhead of a single function call should not be that much slower.

---

Then I thought it might be that Clozure CL is responsible. So I ran the same code in SBCL and even there the behaviour is similar. The difference isn't as big, but it's still pretty big. It's about 22 times slower.

SBCL output when running direct:

Evaluation took:
  1.519 seconds of real time
  1.477893 seconds of total run time (0.996071 user, 0.481822 system)
  97.30% CPU
  12 lambdas converted
  2,583,290,520 processor cycles
  492,536 bytes consed

SBCL output when running as a function:

Evaluation took:
  33.522 seconds of real time
  33.472137 seconds of total run time (33.145166 user, 0.326971 system)
  [ Run times consist of 0.254 seconds GC time, and 33.219 seconds non-GC time. ]
  99.85% CPU
  56,989,918,442 processor cycles
  2,999,581,336 bytes consed

Why is calling the code as a function so much slower? And how do I fix it?

Answer 1

The difference is probably due to the regular expression.

Here the regex is a literal string:

 (cl-ppcre:scan ".*?january.*?agami.*?" 
                (funcall (symbol-function field) record))

The cl-ppcre:scan function has a compiler macro that detects this case and generates a (load-time-value (create-scanner ...)) expression (since the string cannot possibly depend on runtime values, this is acceptable).

The compiler-macro might be applied in your test too, in which case the load-time-value is probably executed only once.

In the following code, however, the regular expression is a runtime value, obtained as an input of the function:

(defun searchx (regex &rest fields) 
  (loop for field in fields 
    append (loop for record in RECORDS
             when (cl-ppcre:scan regex (funcall (symbol-function field) record))
             collect record)))

In that case, the scanner object is built when evaluating scan, i.e. each time the loop iterates over a record.

In order to test this hypothesis, you may want to do the following:

(defun searchx (regex &rest fields) 
  (loop 
    with scanner = (cl-ppcre:create-scanner regex)
    for field in fields 
    append (loop for record in RECORDS
             when (cl-ppcre:scan scanner (funcall (symbol-function field) record))
             collect record)))

Alternatively, do not change the function but give it a scanner:

(time (searchx (cl-ppcre:create-scanner 
                 ".*?january.*?agami.*?")
              'full-name 
              'email))