Muse Spark Open 推理延迟忽高忽低——卡在预处理还是显卡？

先把问题缩小：同一个提示词、同一张图，有时几百毫秒返回，有时要等上几秒，这时不要先猜是显卡慢还是图片解码慢，先把一次请求拆成“预处理 → 传输/排队 → 前向推理”三段，各打一个时间戳。只有三段耗时能横向比较，才能判断波动到底出在 CPU 侧的图片解码与缩放，还是 GPU 侧在等数据、等显存、等批处理凑齐。下面给的是通用埋点骨架，具体函数名要换成你所用推理服务里的对应调用；判断依据只看自己环境里实测出来的分段耗时，不套用任何外部延迟基准。

判断路径：在请求入口、预处理结束、模型调用返回三处打时间戳，把总延迟拆成预处理段、传输排队段、前向段分别统计；波动集中在预处理段，就先查图片解码与缩放；集中在前向段且 GPU 利用率与显存同步起伏，多半是显卡在忙；前向段耗时高但 GPU 利用率很低，通常是显卡在等数据。所有判断以二十次以上固定输入的实测分布为准，首跑与后续跑要分开统计。

在请求入口与模型调用前后各打时间戳

目标是把一次请求切成可比较的三段时间，且每段都用同一个时钟源、同一个单位输出，避免毫秒和秒混用导致误判。建议在请求进入处理函数时记录 t0，预处理（下载/解码/缩放/转张量）完成后记录 t1，模型前向返回后记录 t2。三段即：预处理 = t1 - t0，传输与排队 = t1 到真正进入前向之间的间隔（如果框架内部还有排队，最好再拆一个点），前向 = t2 - t1。用单调时钟，不要用墙上时间，避免系统时间调整造成负值。

import time, json, logging

def handle(req):
    t0 = time.monotonic()
    img = load_and_decode(req.image)      # 替换为实际解码调用
    tensor = preprocess(img, req.size)    # 替换为实际缩放/归一化
    t1 = time.monotonic()
    out = model_infer(tensor)             # 替换为实际推理调用
    t2 = time.monotonic()
    logging.info(json.dumps({
        "req_id": req.id,
        "img_bytes": len(req.image),
        "img_wh": list(req.size),
        "pre_ms": round((t1 - t0) * 1000, 2),
        "infer_ms": round((t2 - t1) * 1000, 2),
        "total_ms": round((t2 - t0) * 1000, 2)
    }, ensure_ascii=False))
    return out

统一输出成一行 JSON，字段固定，方便后面用 grep、jq 或直接导入表格做分布统计。如果推理框架内部有请求队列（比如批处理凑批等待），t1 到真正执行前向之间会有一段等待，建议再打一个 t1b，标记“进入执行器”的时刻，否则排队时间会被算进前向段，误判成显卡慢。埋点本身有开销，但几行取时间戳的调用通常远小于图片解码量级；如果担心影响，可以先用环境变量控制开关，定位完再关掉。

把图片解码与缩放单独计时

“有时快有时慢”最常见的来源之一是输入图片尺寸差异太大：同一批次里混着小缩略图和高分辨率原图，解码和缩放耗时会差出数量级。做法是把解码和缩放从预处理段里再拆出来，分别计时，并记录图片的宽高和字节数，观察耗时是否随尺寸单调上升。

def time_decode(path, repeat=5):
    costs = []
    for _ in range(repeat):
        s = time.monotonic()
        img = load_and_decode(path)
        e = time.monotonic()
        costs.append(round((e - s) * 1000, 2))
    costs.sort()
    return {
        "path": path,
        "runs": costs,
        "min_ms": costs[0],
        "median_ms": costs[len(costs) // 2],
        "max_ms": costs[-1]
    }

同一张图重复解码多次，看最小值和最大值之间的差距：如果同一张图解码耗时波动就很大（比如首次明显偏慢、后续稳定），说明有缓存或磁盘冷读的影响；如果同一张图很稳定，但不同尺寸的图差异明显，说明波动来自输入尺寸而不是运行时抖动。缩放同理，单独测一次“解码后再缩放到目标尺寸”的耗时，和“直接解码”对比，判断缩放占比。记录表可以按“图片标识 / 宽高 / 字节数 / 解码耗时 / 缩放耗时 / 是否首次”排列，把慢请求逐条填进去，很快能看出慢的是哪一类输入。

需要注意：网络下载图片的时间不算解码时间，如果图片来自远端，下载应归到传输段，否则又会把网络抖动误记为预处理慢。可以在下载前后也加一个时间戳，判断慢请求是不是卡在拉取。

观察显存占用与 GPU 利用率是否同步波动

这一步用来区分“显卡在忙”和“显卡在等数据”。在服务运行期间，用固定间隔采样 GPU 利用率和显存占用，与请求日志的时间轴对齐：前向段耗时高、且采样到的 GPU 利用率也高，说明显卡确实在算；前向段耗时高、但 GPU 利用率长期偏低甚至接近空闲，说明计算卡在等输入、等批处理、等锁或等显存分配。

nvidia-smi `--query-gpu`=timestamp,utilization.gpu,memory.used,memory.total \
  `--format`=csv,noheader,nounits -l 1

采样间隔建议先设 1 秒，粒度足够粗看趋势；要抓短时尖峰再降到 200~500 毫秒，但间隔太短会带来额外开销，且 csv 输出量大，定位完就停。对照方式：把一个慢请求的 req_id、三段耗时，与同一时间窗口内的利用率采样并列看，重点看“前向段开始时 GPU 是否已经在跑”。另外记录显存占用的波动：如果显存接近上限、出现反复的分配与释放，前向段可能出现不稳定；如果显存平稳而利用率低，则更偏向数据供给或排队问题。这里只做观察，不建议靠调大 batch 或提高并发去“压测出结论”，那会改变问题本身。

固定输入跑二十次看首次与后续差异

冷启动成本必须和稳定态成本分开算，否则第一次请求的耗时会把整体均值拉高，看起来像“随机变慢”。用同一张图、同一段提示词、同样参数，连续跑二十次以上，逐次记录三段耗时，并把第 1 次与第 2 次及之后分开统计。

# 伪代码：固定输入重复调用，输出逐次明细
for i in range(20):
    r = handle(fixed_req)
    print(i, r.pre_ms, r.infer_ms, r.total_ms)

统计时至少给出：首次的预处理、前向耗时；第 2 次到第 20 次的最小值、中位数、最大值。判断规则可以先用这个：首次明显高于后续，且后续趋于平稳，说明差异主要来自模型加载、显存分配、算子编译或图片缓存这类一次性成本；后续仍然忽高忽低，才需要回到预处理段和前向段继续拆。这里的数值必须来自你自己环境的实测记录，不要拿别处的延迟数字当参照。

按计时占比决定先优化哪一段

拿到二十次以上的分段数据后，先算占比：预处理段、传输排队段、前向段各占中位总耗时的比例，以及各段的最大值相对中位数的偏离程度。规则很简单——哪一段占比最高、或者哪一段的波动幅度最大，就先动哪一段；两段都高时，先处理波动大的那段，因为波动往往才是“忽高忽低”的直接来源。

预处理段占主导：先查图片尺寸是否统一、是否重复解码、缩放是否在 CPU 上单线程执行。
传输排队段占主导：先查请求是否在队列里等批处理凑批、是否被并发限流。
前向段占主导且 GPU 利用率同步升高：属于显卡在忙，优化方向是减少无效计算或调整输入规模。
前向段占主导但 GPU 利用率低：属于显卡在等数据，先解决数据供给和排队，而不是换卡。

每次只改一处，改完用同一批固定输入重跑同样的二十次，对比同一张记录表里三段的占比是否真的变化。如果改了预处理后前向段占比反而上升，说明瓶颈已经转移，需要重新按新数据排序，而不是继续沿用旧结论。验证方式始终是同一张输入、同一套埋点、同样的统计口径；只要口径变了，前后数据就不可比。