为什么时间宏声称慢速函数调用的经过时间非常短？

Question

正在看 clojure for the brave and true 第 9 章底部的练习（特别是搜索多个引擎的最后一个和 return 每个引擎的第一个命中）

我用 slurp 部分嘲笑实际搜索是这样的：

(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)
    (map deref futs)))

（我知道这里的 return 是一个列表，练习需要一个向量，但可以只做一个 into...）

但是当我运行在 REPL

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

我添加 doall 后似乎需要 2 秒（因为映射 return 是一个惰性序列，我认为除非我消耗序列，否则任何期货甚至都不会开始，(last futs) 似乎也有效）但是当我在 REPL 中使用 time 宏时，它报告几乎没有消耗时间，即使它需要 2 秒：

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

这里的 time 宏是怎么回事？

Answer 1

TL;DR: Lazy seqs 不适合 time 宏，你的函数 get-first-hit-from-each return 是一个惰性 seq。要使惰性序列与 time 一起工作，请按照 documentation 的建议将它们包装在 doall 中。请参阅下面的更完整的思考过程：

下面是clojure.core(source)中time宏的定义：

(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 的 return 值保存在 ret# 中，然后立即打印经过的时间？只有在那之后 ret# 才会得到 returned。这里的关键是你的函数 get-first-hit-from-each return 是一个惰性序列（因为 map return 是一个惰性序列）：

(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 打印不准确的原因。 None 的计算长度的东西实际上在打印输出之前达到运行。

为了解决这个问题并获得准确的时间，我们需要确保对惰性序列的评估，这可以通过在许多可能的地方战略性地放置一个 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"))))

Answer 2

您的设置中发生了一些奇怪的事情。它对我来说按预期工作，需要 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。

更新：

我发现了我的错误。我在第 15 行不小心使用了 mapv 而不是 map。这迫使它等待每次调用 deref。如果你在这里使用map，你会得到一个lazy seq的lazy seq并且函数在定时器到期之前结束（两次=> 4秒）。

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

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

我总是建议使用 mapv 而不是 map。还有一个 filterv 可用。如有疑问，请使用 (vec ...) 将输出强制转换为一个漂亮、急切的向量，以摆脱因懒惰而引起的头痛。

也许您会需要一百次中的一次 lazy seq 提供的功能。其他时候这是一个问题，因为您无法预测语句的执行顺序。

P.S.

参见 this list of documentation，包括精彩的 Clojure 备忘单。

P.P.S.

OP 是正确的，理想情况下，每个查询都应该在一个单独的线程中并行运行（每个 future 使用一个单独的线程）。问题又是由于懒惰 map 行为。

在最后的 println 中，futs 的惰性列表中的每个元素直到 println 需要时才会被评估。因此，它们甚至要等到稍后才开始，按顺序排列。这违背了并行执行的预期目标。同样，惰性序列行为是原因。

解决方法：在 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"

为什么时间宏声称慢速函数调用的经过时间非常短？

why is the time macro claiming a very short elapsed time for slow function call?

future

clojure

lazy-evaluation

lazy-sequences

更新：

P.S.

P.P.S.