并发任务执行时间测量偏差问题排查与准确测量方法咨询

在并发调用函数（10次）并测量总执行时间时，发现实际耗时与各线程上报耗时存在显著偏差，且仅在连接服务器B时出现该情况：
10线程场景下：

• 服务器A：总耗时200ms，单线程耗时约80ms
• 服务器B：总耗时约2分钟，单线程耗时约2-10s

服务器B的线程起止时间无法反映正确耗时，必须手动计算总耗时。简化代码如下：

(defn- time-taken [f]
  (let [start (System/nanoTime)
        result (f)]
    [(- (System/nanoTime) start) result]))

(defn perform-task []
  ; 调用REST API及其他逻辑
  :done)

(defn run-concurrent-tasks [n]
  (let [futures (mapv (fn [_] (future (time-taken perform-task))) (range n))]
    (mapv deref futures)))

(run-concurrent-tasks 10)

执行run-concurrent-tasks时，各线程上报的单任务耗时约1-2s，但程序实际总耗时约2分钟（外部手动测量）。通过REPL运行可复现服务器A、B的耗时差异，暂未找到解决方案。

核心问题 #

1. 为何连接服务器B时，实际耗时与线程上报耗时存在巨大偏差？
2. 当前使用time-taken或创建/使用future的方式是否存在缺陷？
3. 如何准确测量所有并发任务完成的总耗时？

1. 耗时偏差的根本原因 #

核心原因是服务器B存在并发请求限流/排队机制：

• 当发起10个并发请求时，服务器B并未同时处理所有请求，而是将超出处理阈值的请求放入队列等待，导致后续请求需等前面的请求完成后才能开始执行。
• 每个time-taken测量的只是单个请求被服务器实际处理的时间，而非从客户端发起请求到收到响应的完整周期（包含服务器端排队等待的时间）。而手动测量的总耗时是从第一个请求发起，到最后一个请求完成的完整时间，自然远大于单个任务的处理时间之和。
• 服务器A无此类限流机制，所有请求可同时处理，因此总耗时接近单个请求的处理时间（并发执行），偏差极小。

另外，若客户端使用的future线程池线程数不足，会导致任务在客户端侧排队，这段排队时间不会被time-taken计入，也会加剧偏差，但结合场景来看，服务器端限流是主要原因。

2. time-taken与future的使用缺陷 #

• time-taken本身逻辑无误，能准确测量perform-task在当前线程中的执行时间，但它无法捕获任务在客户端线程池中的排队等待时间，也无法感知服务器端的排队延迟（如果perform-task的API调用逻辑没有完整阻塞等待响应的话）。
• future的使用本身没有问题，但Clojure默认的future线程池（forkjoin.commonPool）线程数有限，若并发任务数超过线程池容量，会导致任务在客户端排队，这段时间不会被单个任务的time-taken统计到，进而出现总耗时与单任务耗时之和的偏差。

3. 准确测量总耗时的方法 #

要准确测量所有并发任务从启动到全部完成的总耗时，需将计时起点放在所有任务创建之前，终点放在最后一个任务完成之后，而非依赖单个任务的计时结果。

修正后的代码 #

(defn- time-taken [f]
  (let [start (System/nanoTime)
        result (f)]
    [(- (System/nanoTime) start) result]))

(defn perform-task []
  ; 调用REST API及其他逻辑（确保是同步阻塞调用）
  :done)

(defn run-concurrent-tasks [n]
  (let [total-start (System/nanoTime) ; 总计时起点：所有任务开始前
        futures (mapv (fn [_] (future (time-taken perform-task))) (range n))
        task-results (mapv deref futures) ; 等待所有任务完成
        total-end (System/nanoTime) ; 总计时终点：最后一个任务完成后
        total-time-ms (/ (- total-end total-start) 1e6)
        task-times-ms (mapv #(/ (first %) 1e6) task-results)]
    {:total-execution-time-ms total-time-ms
     :individual-task-times-ms task-times-ms}))

(run-concurrent-tasks 10)

额外优化建议 #

• 若怀疑客户端线程池容量不足，可自定义线程池确保有足够线程发起并发请求：

(require '[clojure.core.async :as async])

(defn run-concurrent-tasks-with-custom-pool [n thread-count]
  (let [total-start (System/nanoTime)
        custom-pool (async/thread-pool thread-count) ; 指定线程数
        futures (mapv (fn [_] (future-call custom-pool #(time-taken perform-task))) (range n))
        task-results (mapv deref futures)
        total-end (System/nanoTime)
        total-time-ms (/ (- total-end total-start) 1e6)
        task-times-ms (mapv #(/ (first %) 1e6) task-results)]
    {:total-execution-time-ms total-time-ms
     :individual-task-times-ms task-times-ms}))

• 检查perform-task中的API调用逻辑，确保是同步阻塞调用，这样time-taken才能捕获从请求发起至响应接收的完整时间（包括服务器端排队和处理）。若使用异步调用，需调整逻辑等待异步操作完成后再结束计时。
• 针对服务器B的限流，可在客户端实现请求排队或限流，避免触发服务器的限流机制，同时更精准地控制并发请求数。

内容的提问来源于stack exchange，提问作者mark_iv