Почему вызов кода как функции занимает больше времени, чем прямой вызов в Clozure Common lisp?

Question

У меня около 900000 записей:

(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")
    ...))

(они читаются из файла. Приведенный выше код приведен только в качестве примера. Он помогает показать внутреннюю структуру этих данных.)

Для быстрого создания прототипа я использую псевдонимы для селекторов:

(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))

---

Теперь я запускаю:

(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)))

Выводы repl:

...
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.
...

---

Определите функцию, выполняющую то же самое:

(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)))

И затем вызовите ее:

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

Вывод:

...
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.
...

Это почти в 70 раз медленнее? !!

Я подумал, может быть, это проблема компьютера. Я запустил один и тот же код на двух разных машинах. MacBook Air и MacBook Pro. Индивидуальные сроки варьируются, но поведение соответствует. Вызов его как функции занимает гораздо больше времени, чем вызов непосредственно на обеих машинах. Конечно, издержки одиночного вызова функции не должны быть намного медленнее.

---

Тогда я подумал, что, возможно, ответственность за это несет Clozure CL. Таким образом, я запускал тот же код в SBCL, и даже там поведение похожее. Разница не такая большая, но все же довольно большая. Это примерно в 22 раза медленнее.

Вывод SBCL при прямом запуске:

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 при запуске в качестве функции:

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

Почему вызываетсякод как функция намного медленнее? И как мне это исправить?

Answer 1

Различие, вероятно, связано с регулярным выражением.

Здесь регулярное выражение является литеральной строкой:

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

Функция cl-ppcre:scan имеет макрос компилятора, который обнаруживает этот случай игенерирует выражение (load-time-value (create-scanner ...)) (поскольку строка не может зависеть от значений времени выполнения, это допустимо).

Макрос-компилятор может также применяться в вашем тесте, и в этом случае значение времени загрузки равновероятно, выполняется только один раз.

Однако в следующем коде регулярное выражение является значением времени выполнения, полученным в качестве входных данных функции:

(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)))

В этом случае объект сканерасоздается при оценке scan, т. е. каждый раз, когда цикл перебирает запись.

Чтобы проверить эту гипотезу, вы можете сделать следующее:

(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)))

В качестве альтернативы,не меняйте функцию, а дайте ей сканер:

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