I have around 900000 RECORDS:
(defparameter RECORDS '((293847 "john menk" "[email protected]" 0123456789 2300 2760 "CHEQUE" 012345 "menk freeway" "high rose") (244841 "january agami" "[email protected]" 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?
