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

Question

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

我用 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)))

（我知道这里的返回是一个列表，练习要求一个向量，但可以为此做一个into...）

但是当我在 REPL 中运行它时

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

在我添加 doall 后似乎需要 2 秒（因为 map 返回一个惰性序列，我认为除非我使用序列，否则任何期货都不会开始，(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：惰性序列不能与 time 宏配合使用，而您的函数 get-first-hit-from-each 返回一个惰性序列。要使惰性序列与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 的返回值保存在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"))))

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，你会得到一个惰性序列的惰性序列，并且函数在计时器到期之前结束（两次 => 4 秒）。

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

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

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

也许一百分之一的时候你会需要惰性序列提供的功能。其他时候这是一个问题，因为您无法预测语句的执行顺序。

附言

请参阅 this list of documentation，包括精彩的 Clojure CheatSheet。

附言

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"