如何使用Tufte分析多线程clojure结果

Question

Tutfe是一个分析库，非常适合理解运行时的组成，特别是在复杂的调用堆栈中。

当我在我的项目中运行它时，我认为性能昂贵的一段代码并没有在结果中注册为高度冒犯者，这导致我发现Tufte (合理地)只捕获了线程本地结果。

文档表明，它具有内置的绑定，可以使用{:dynamic? true}选项检测其他线程上的累积时间，但似乎还需要更多绑定才能捕获其他线程上的累积时间，例如由pmap启动的线程

以下是最初的Tufte演示，并引入了一些多线程：

(require '[taoensso.tufte :as tufte :refer (defnp p profiled profile)])

;; We'll request to send `profile` stats to `println`:
(tufte/add-basic-println-handler! {})

;;; Let's define a couple dummy fns to simulate doing some expensive work
(defn get-x [] (Thread/sleep 500)             "x val")
(defn get-y []
  (pmap
    #(do
        (Thread/sleep 500)
        (print %))
    (range 10)))

;; How do these fns perform? Let's check:

(profile ; Profile any `p` forms called during body execution
  {:dynamic? true} ; Profiling options; we'll use the defaults for now
  (dotimes [_ 5]
    (p :get-x (get-x))
    (p :get-y (get-y))))

输出表明println语句强制线程求值。然而，get-y累积时间并没有显示在结果中：

2187306594=> nil
=> #{:basic-println}
=> #'user/get-x
=> #'user/get-y
8904365271703695842110783956243415760829=> nil

       pId      nCalls       Min        Max       MAD      Mean   Time% Time
    :get-x           5  500.52ms   504.84ms    1.44ms  502.44ms     100 2.51s
    :get-y           5   90.67μs   581.91μs   162.2μs  269.29μs       0 1.35ms
Clock Time                                                          100 2.51s
Accounted Time                                                      100 2.51s

Answer 1

答案:延迟初始化。尽管数据正在打印到屏幕上，但在被监视的表单get-y之外，执行打印的是(profile...)表单的末尾。

这将产生相同的效果：

(profile ; Profile any `p` forms called during body execution
  {:dynamic? true} ; Profiling options; we'll use the defaults for now
  (dotimes [_ 5]
    (p :get-x (get-x))
    (doall (p :get-y (get-y)))))

30167894521045768392530798241651268940371023657894=> nil

           pId      nCalls       Min        Max       MAD      Mean   Time% Time
        :get-x           5  500.07ms   504.58ms    1.41ms  503.08ms      50 2.52s
        :get-y           5   80.25μs   126.18μs   15.98μs  104.84μs       0 524.18μs
    Clock Time                                                          100 5.03s
Accounted Time                                                           50 2.52s

而这个实现了get-y配置文件中的惰性序列：

(profile ; Profile any `p` forms called during body execution
  {:dynamic? true} ; Profiling options; we'll use the defaults for now
  (dotimes [_ 5]
    (p :get-x (get-x))
    (p :get-y (doall (get-y)))))

12037645987105892436354169872031089546721058729634=> nil

           pId      nCalls       Min        Max       MAD      Mean   Time% Time
        :get-x           5  502.54ms   504.71ms   705.6μs   503.5ms      50 2.52s
        :get-y           5  501.69ms   505.68ms    1.05ms  503.06ms      50 2.52s
    Clock Time                                                          100 5.03s
Accounted Time                                                          100 5.03s

了解这一点对于分析体验很重要，因为在处理惰性序列时，您会意识到它们是如何使用的性能，而不是序列本身：

(profile ; Profile any `p` forms called during body execution
  {:dynamic? true} ; Profiling options; we'll use the defaults for now
  (dotimes [_ 5]
    (p :get-x (get-x))
    (p ::realize-y
       (doall (p :get-y (get-y))))))

06538947123410695278450678913223071958645126380479=> nil

            pId      nCalls       Min        Max       MAD      Mean   Time% Time
:user/realize-y           5  503.29ms   504.86ms  458.12μs  504.37ms      50 2.52s
         :get-x           5  500.13ms   505.06ms     1.4ms  503.64ms      50 2.52s
         :get-y           5    86.0μs     1.15ms  331.81μs  322.94μs       0 1.61ms
     Clock Time                                                          100 5.04s
 Accounted Time                                                          100 5.04s