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

Вкратце: ленивые последовательности плохо сочетаются с макросом time, а ваша функция get-first-hit-from-each возвращает ленивую последовательность. Чтобы ленивые последовательности работали с time, оберните их в doall, как это предлагается в документации< /а>. См. Ниже более полный мыслительный процесс:

Ниже приводится определение макроса time в clojure.core (источник):

(defmacro time
  "Evaluates expr and prints the time it took.  Returns the value of
 expr."
  {:added "1.0"}
  [expr]
  `(let [start# (. System (nanoTime))
         ret# ~expr]
     (prn (str "Elapsed time: " (/ (double (- (. System (nanoTime)) start#)) 1000000.0) " msecs"))
     ret#))

Обратите внимание, как макрос сохраняет возвращаемое значение expr в ret#, сразу после чего печатает прошедшее время? Только после этого возвращается ret#. Ключевым моментом здесь является то, что ваша функция get-first-hit-from-each возвращает ленивую последовательность (поскольку map возвращает ленивую последовательность):

(type (get-first-hit-from-each "gray+cat" '("google" "bing")))
;; => clojure.lang.LazySeq

Таким образом, когда вы выполняете (time (get-first-hit-from-each "gray+cat" '("google" "bing"))), в ret# сохраняется ленивая последовательность, которая на самом деле не оценивается, пока мы не попытаемся использовать ее значение...

Мы можем проверить, была ли вычислена ленивая последовательность, используя функцию realized?. Итак, давайте настроим макрос time, добавив строку, чтобы проверить, было ли вычислено ret#, сразу после печати прошедшего времени:

(defmacro my-time
  [expr]
  `(let [start# (. System (nanoTime))
         ret# ~expr]
     (prn (str "Elapsed time: " (/ (double (- (. System (nanoTime)) start#)) 1000000.0) " msecs"))
     (prn (realized? ret#)) ;; has the lazy sequence been evaluated?
     ret#))

Теперь тестируем:

(my-time (get-first-hit-from-each "gray+cat" '("google" "bing")))
"Elapsed time: 0.223054 msecs"
false
;; => ("https://www.google.com/search?q%3Dgray+cat" "https://www.bing.com/search?q%3Dgray+cat")

Нет... так вот почему time печатается неточно. Ни одна из вычислительно-длинных вещей фактически не запускается до того, как будет сделана распечатка.

Чтобы исправить это и получить точное время, нам нужно обеспечить оценку ленивой последовательности, что можно сделать, стратегически поместив doall в кучу возможных мест, либо внутри вашей функции, обернув map:

(defn get-first-hit-from-each
  [query engines]
  (let [futs (map (fn [engine]
                    (future (search-for query engine))) engines)]
    (doall futs)
    (doall (map deref futs))))
;; => #'propeller.core/get-first-hit-from-each

(time (get-first-hit-from-each "gray+cat" '("google" "bing")))
"Elapsed time: 2005.478689 msecs"
;; => ("https://www.google.com/search?q%3Dgray+cat" "https://www.bing.com/search?q%3Dgray+cat")

или внутри time, оборачивая вызов функции:

(time (doall (get-first-hit-from-each "gray+cat" '("google" "bing"))))

Что-то странное происходит в вашей установке. Он работает, как и ожидалось, за 4 секунды:

(ns tst.demo.core
  (:use tupelo.core tupelo.test))

(defn search-for
      [query engine]
      (Thread/sleep 2000)
      (format "https://www.%s.com/search?q%%3D%s", engine query))

(defn get-first-hit-from-each
      [query engines]
      (let [futs (map (fn [engine]
                        (future (search-for query engine)))
                      engines)]
        ; (doall futs)
        (mapv #(println (deref %)) futs)))

(dotest
  (time
    (get-first-hit-from-each "gray+cat" '("google" "bing"))))

с результатом

--------------------------------------
   Clojure 1.10.2-alpha1    Java 14
--------------------------------------

Testing tst.demo.core
https://www.google.com/search?q%3Dgray+cat
https://www.bing.com/search?q%3Dgray+cat
"Elapsed time: 4001.384795 msecs"

Я даже не использовал doall.

Обновлять:

Я нашел свою ошибку. Я случайно использовал mapv вместо map в строке 15. Это заставляет его ждать каждого вызова deref. Если вы используете здесь map, вы получите ленивую последовательность ленивой последовательности, и функция завершится до истечения времени таймера (дважды => 4 секунды).

--------------------------------------
   Clojure 1.10.2-alpha1    Java 14
--------------------------------------

Testing tst.demo.core
"Elapsed time: 0.182797 msecs"

Я всегда рекомендую использовать mapv вместо map. Также имеется filterv. Если вы сомневаетесь, преобразуйте выходные данные в красивый энергичный вектор, используя (vec ...), чтобы избавить себя от головной боли из-за лени.

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

P.S.

См. этот список документации, включая прекрасную CheatSheet по Clojure.

P.P.S.

ОП прав, что в идеале каждый запрос должен выполняться параллельно в отдельном потоке (каждый future использует отдельный поток). Проблема опять же в ленивом map поведении.

В конце println каждый элемент в ленивом списке из futs не оценивается до тех пор, пока не потребуется println. Таким образом, они даже не начинаются позже, по очереди. Это противоречит намеченной цели параллельного выполнения. Опять же, причиной является поведение lazy-seq.

Лекарство: делайте все явным и нетерпеливым в 99+ процентах случаев (т. е. mapv):

(defn search-for
      [query engine]
      (Thread/sleep 2000)
      (format "https://www.%s.com/search?q%%3D%s", engine query))

(defn get-first-hit-from-each
      [query engines]
      (let [futs (mapv (fn [engine]
                         (future (search-for query engine)))
                       engines)]
        (mapv #(println (deref %)) futs)))

с результатом:

Testing tst.demo.core
https://www.google.com/search?q%3Dgray+cat
https://www.bing.com/search?q%3Dgray+cat
"Elapsed time: 2003.770331 msecs"