Skip to content

R8 · Display Performance Source Ownership 与 Gap Classification 收口 ​

背景 ​

Session 5c3a61d4-d6f3-4a92-8e17-b9bef32d65b3(iPhone17,3 / iOS 18.2.1, 2026-09-18 10:35-10:36,目标 App 百度网盘)暴露四个 P0 根因:

  1. ios.foreground.fps 同时存在 pmd3.graphics.raw 与 pmd3.activity-trace.frame-lifetime.raw 两个事实来源(Registry 契约已声明 ActivityTrace 单一所有权,但 metric_engine.py::_graphics_metrics 仍在从 CoreAnimationFramesPerSecond 投影同一个 metricID)。
  2. Live FPS 用 hostNow - lastHostReceiveTime 外推 source-time 窗口,Host 静默 ≥2s 即判定 candidate-idle/FPS=0;真机证实 ActivityTrace host 交付 可批量延迟达 ~6.7s,源端仍以 ~16.6ms 正常节奏出帧。
  3. FrameLifetimeDecoder 仅验证 prev_frame == previous.end_time 的结构连续 性即标记 quality=valid 并计算 FrameTime,未验证该 interval 相对 refresh_interval 是否是一个合理的单帧/少帧间隔;真机记录了两次异常 (deltaSeed=64/presentationDelta=2879.367ms、deltaSeed=31/ presentationDelta=29876.021ms),仍被标记 valid 并进入 FrameTime/P95/ Jitter 统计。
  4. Offline Frame Report(analyze_display_frames)与 Live (DisplayPerformanceProjector)虽然共享同一个 decoder 产出的 quality 字段,但两侧对该字段的下游处理不完整,导致 sourceGapCount=0 与 averageFrameTimeMs=1740.61ms 同时出现。

已落地 ​

  • Phase A:metric_engine.py::_graphics_metrics 不再投影 ios.foreground.fps;Graphics 仅保留三项 GPU 利用率正式 metric。新增 RealtimeMetricProjector._graphics_observed_fps 作为 diagnostics-only 字段 (frame_continuity_telemetry()["graphicsObservedFPS"]),供旧版 CoreProfile FrameTime 新鲜度交叉诊断使用,不再进入 Registry/Report。
  • Phase B:DisplayPerformanceProjector.snapshot() 移除用 host 时间外推 source clock 后直接判定 0 帧的逻辑;改为显式 freshness gate (FRESHNESS_STALE_HOST_GAP_NS,等于 FPS 窗口宽度 1s):host 静默超过该值时 返回 quality=stale-source/value=None,不再伪造 candidate-idle/0。
  • Phase C:FrameLifetimeDecoder.decode() 新增 GAP_REFRESH_MULTIPLE_THRESHOLD=12(约 200ms@60Hz)的动态 gap gate:结构 连续但 presentationDelta / refreshInterval 超过该倍数时标记 quality=source-gap、frameTimeMs=None,并强制下一条 event 重新 warmup (_pending_gap_rewarm),不允许跳过锚点直接恢复 valid。
  • Phase D:decode() 输出新增 diagnostics-only 字段 frameSeedDelta/sourcePresentationDeltaMs/hostReceiveDeltaMs/ deliveryLagDeltaMs/refreshMultiple,均不参与 FrameTime/FPS 公式。
  • Phase E:Live 侧 _rolling_frame_times(P95/Jitter 输入)已通过 decoder 的 quality/frameTimeMs 门禁天然排除 source-gap;补齐 source-gap quality 到 _latest_frame_quality 更新分支,避免其被静默吞掉。
  • Phase F:analyze_display_frames(Offline Frame Report)新增 source-gap 分类分支与 sourceGapEventCount/discontinuityCount/ largestSourceGapMs/continuousSegmentCount/validIntervalCount/ validCoverageSeconds 诊断字段;averageFrameTimeMs 等统计口径不再被跨 gap 的巨大 interval 污染。Live 与 Offline 共享同一枚 decoder 产出的 quality 字段,不存在两套独立维护的 continuity 规则。
  • Phase G:新增 build_provenance.py:collectorCoreVersion/ collectorCoreSHA256(对 collector-core 自身源码计算,不依赖构建脚本) 始终存在;perfowlVersion/perfowlBuildNumber/perfowlGitCommit 取自 macOS App 启动时注入的环境变量(CollectorSupervisor.environment(for:) 读取 CFBundleShortVersionString/CFBundleVersion/PERFOWL_GIT_COMMIT)。 RawSessionRecorder 在 Session 开始时冻结一次并写入 manifest.json.buildProvenance。

验证 ​

  • Python sidecar(冻结 CPython 3.12 x86_64 + pymobiledevice3 11.3.1): 564/564(含新增 test_e4_display_gap_regression.py 11 项、 test_build_provenance.py 3 项回归)。
  • Swift:182 项,181 通过;testStoppedCoreWithoutDeliveryIsMarkedPartial 为既有计时敏感 flake(单独运行必过,与本次改动无关,未新增/未修复)。
  • 新增 E4 真机数据回归 fixture:真实 Session 的两处异常 (2879.367ms/29876.021ms gap、6689ms host 延迟 vs 16.641ms 源端间隔)已固化 为单元测试,防止回归。

R8-Fix(Build 62 真机复测后,2026-09-18) ​

Build 62 真机 Session 062995a9-6bbb-455e-b8bf-faa17622d558(iPhone17,3 / iOS 18.2.1,manifest 确认 collectorCoreVersion=r8-display-source-ownership.v1) 证明 R8 的偽装消除按设计生效——但也第一次暴露真正的 P0:数据源本身。

事实基线:60 秒内 Graphics 观察到约 58 FPS(graphicsObservedFPS), ActivityTrace FrameLifetime 却只交付 2 条(frameSeed 333211→333212, 第二条 FrameTime=16.639291ms、refreshMultiple=0.998、60.0024Hz,decoder/ timebase/公式全部正确)。20 个产品 sample 中 FPS 全为 null(missing 9 / stale-source 11),FrameTime 有效 1 个,P95/Jitter warmup——这正是 R8 期望 的诚实缺失,不再伪造。真正问题是 iOS 18.2.1 上 ActivityTrace 未形成可靠连续 实时流。

本轮不再动 Display 计算公式,改为诊断 + 修复暴露出的具体缺陷:

  • P0 acquisition census:_ActivityTraceFilteredStream 在 source-edge 白名单之前插入 ActivityTraceAcquisitionCensus,统计 totalMessageCount / frameLifetimeMatchedCount / frameLifetimeRejectedCount / rejectedIdentityTopN(subsystem/category/name) / first-last callback 时间 / rawCallbackRateHz / streamEnded;seal 时写入 display-acquisition-census.json 与 manifest.displayAcquisitionCensus。 下一次真机运行即可区分"tap 静默(raw≈2, streamEnded)"与"白名单漏掉真实帧 (raw≫2, rejectedIdentityTopN)"两种完全不同的根因——白名单本身保持不变。
  • P1 prepare_transport:ActivityTraceFrameLifetimeRawAdapter 补 prepare_transport()(声明为 start-time-activated),修复 source_preparation 把它标记 transport-preparation-not-supported/ preparationState=failed 而运行时实际正常启动的自相矛盾。
  • P1 host timestamp:raw_events() 捕获一次 time.monotonic_ns(),同时 传给 decode(host_receive_monotonic_ns=) 与 RawEventEnvelope,使 Phase D 的 hostReceiveDeltaMs/deliveryLagDeltaMs 在真机不再恒为 null。
  • P1 coverage 门禁:online INVALID_QUALITIES 增加 source-gap/delivery-gap/discontinuity/stale-source;online 与 offline frame summary 增加 validIntervalCount/validCoverageSeconds/ coverageSufficient/coverageReason(阈值 5 个有效 interval),避免"1 个 interval 仍报 Avg FPS 60"。数值字段保持数学正确,仅新增 coverage 判定。
  • P2 provenance:build_provenance.py 优先读取构建期写入的 collector_core_build_stamp.json(--add-data 打进 bundle),frozen 环境 不再 glob 不到 .py 而退化成 SHA256("")=e3b0c442…;build-sidecar-core.sh 写入该 stamp(含 SOURCE_HASH 与 git commit);build-app.sh 将 PerfowlGitCommit 写入 Info.plist,CollectorSupervisor.environment(for:) 从 Info.plist 读取并透传 PERFOWL_GIT_COMMIT。

验证:Python 全量 572/572(新增 test_display_acquisition_diagnostics.py 7 项、 test_build_provenance.py 更新);Swift 全量 183/183(+1 testCollectorSupervisorEnvironmentForwardsGitCommitProvenance)绿灯, testStoppedCoreWithoutDeliveryIsMarkedPartial 为既有 ~50% 计时敏感 flake (已在 clean HEAD 上复现同样 fail/pass 交替,与本次改动无关)。

验证:Python 全量 572/572;Swift 全量 183/183。

R8-Fix-2(Build 63 真机复测后,2026-09-18,status partial · E4 诊断) ​

Build 63 真机 Session 8f7ab912-92d4-4ec3-a7e7-9250ee3cf1c0(manifest 确认 perfowlBuildNumber=63、perfowlGitCommit=d4b6d76、collectorCoreSHA256= d54a752… 非空——P2 provenance 修复经 E4 验证;host delivery diagnostics hostReceiveDeltaMs=3354ms 实际写出——P1 修复经 E4 验证)。

acquisition census 一次性把根因定死,且与前一次 Session 完全不同:

层062995a98f7ab912
tap 生存2 条健全:5636 msg / 141Hz / streamEnded=false
白名单—正确:reject 全为正当非 FrameLifetime(CAImageQueue/RenderInterval/Commit…)
FrameLifetime 匹配2652
到达 recorder—仅 5(frameSeed 371816–371823)

即:652 条可解码 FrameLifetime 送达,只有 5 条进入录制管线,647 条(99.2%) 在过滤器与 recorder 之间丢失。 决定性证据(E4):

  • display.frame-lifetime.raw 生事件 = 5(生事件无条件记录,非质量门问题,是 消费问题)。
  • 静默丢失:droppedEventHighWater=0。647 条被泵入 2048 bound queue(<2048 不 溢出 drop),未被 drain,session 结束时丢弃。
  • 非 throughput 律速:writer 在 28.66s 中约 20s(70%)空闲(>1s 空白 12 次)。
  • display adapter 内部 sequence 只到 5 = raw_events() 只 yield 5 次;且 display task 既未 fail(firstFatalSource=None)也未 complete(streamEnded=false)→ session 结束时仍在运行/阻塞。
  • FTI-008 既有诊断吻合:frameTimeMissingWhileGraphicsFPSPositiveCount=14。

因果链:source 健全(652) → recorder 消费 5 → live projector 也只收 5 → metrics.csv 20 sample 中 FPS 0/20、FrameTime 3/20 → UI 空白(Refresh Rate 仍出,因其由 refresh_interval 单独算出)。

本轮实现(观测性 + 修复必要前置) ​

用户批准"再现 fixture → 修复"。离线再现(test_display_acquisition_diagnostics.py 的 SubscriptionBacklogAccountingTests)证明 **pump + consumer + writer_async_lock

  • 单 worker executor 的隔离模式本身会完整 drain(650/650)**——即 starvation 是 full multi-source orchestration 固有,离线无法复现(依赖真机 asyncio 时序)。因此 先落地"把静默丢失变成可测量、精确定位 drain 停止边界"的观测性,而非盲改调度器 (AGENTS.md 效率/诚实门禁):
  • Pmd3Subscription 新增 delivered_event_count / consumed_event_count / undrained_at_close / pending_event_count;__anext__ 两个返回路径都计入 consumed,_pump 计入 delivered,aclose 记录 queue 深度。
  • ActivityTraceFrameLifetimeRawAdapter.acquisition_census() 附带 subscription 区块;并在 stop() 丢弃 subscription 引用前快照(修复一个同批发现的真机 bug:stop 先置 None 导致 seal 时读到 None,实机计量本会失效)。
  • 因此 Build 64 的 display-acquisition-census.json.subscription 将直接给出 deliveredEventCount(应≈652)与 undrainedAtClose(应≈647),把"消费者 starvation"从推断变为实测,用于定向修复并提供前后对比证据。

修改文件:pmd3_backend.py、display_performance.py、 tests/test_display_acquisition_diagnostics.py。验证:Python 574/574;离线再现 测试 PASS(隔离模式完整 drain,实机 shape「5/652 + undrained>600」被单测固化)。

未关闭门禁 ​

  • 下一步优先(需真机):用 Build 64 重跑真机,读取 display-acquisition-census.json.subscription。确认 undrainedAtClose≈647 后,定向修复 consumer 的 multi-source drain 公平性(候选:display 高频源专用 drain 批量/独立 writer 通道/close 前 drain backlog),并用真机前后对比 consumedEventCount 验收(效率门禁要求前后证据)。
  • 交付门禁:本批为 partial。ad-hoc 签名 Build 64 仅供真机诊断;Developer ID 签名/公证/stapling 未做(凭据缺失,blocked)。双远程推送与企业微信 Webhook 通知待用户确认后执行(外发操作)。
  • Display-only / Startup+Display / 静态动态切换三场真机验收仍开放。

R8-Fix-3(Build 64 根因闭环 + 非阻塞 Wire 修复,2026-09-18,status implemented · gate-open) ​

Build 64 的两轮真机诊断把 R8-Fix-2 的“consumer starvation”进一步收敛到了单一高置信度根因:collector 在 asyncio 事件循环线程上同步写 stdout wire,Host 读取稍慢时 OS pipe buffer 填满,print(..., flush=True) 阻塞整个事件循环。 这会同时冻结所有 source consumer;ActivityTrace 本身继续把 FrameLifetime 泵入 subscription queue,但 raw_events() 无法继续 __anext__(),最终形成数百条 undrained backlog。

Build 64 决定性 E4 证据 ​

两轮 Session 均确认 tap/source 健全、白名单正确、queue 无 high-water drop,但 consumer 几乎停止:

Build 64 样本raw callbackFrameLifetime deliveredconsumedundrainedAtClosedropped
A4454 msg / 123.00 Hz54845440
B3270 msg / 107.95 Hz43024280

这与实测时序完全吻合:早期有少量正常数据,随后所有 source 都出现数秒级停顿;Display 高频源最先在 bridge queue 中积压,因此 FPS/FrameTime 最明显地表现为 missing。离线的普通 pump + consumer fixture 不复现,是因为它没有真实的慢 stdout pipe。

根因离线复现 ​

使用“无 reader / 慢 reader 的 pipe + event-loop 线程同步 os.write”做最小复现时,pipe buffer 填满后整个 loop 直接挂住,连 consumer timeout/heartbeat 都无法继续推进。该行为与真机“每 5~10 秒才恢复一小段”的模式一致:真机 Swift 端并非永久不读,而是读取速度不足时周期性解除 pipe back-pressure。

最终修复 ​

perfowl_collector_core_cli.py 新增 _WireOutput:

  1. 所有 collector → Mac App NDJSON wire 写操作移到独立 daemon writer thread;asyncio capture loop 的 emit() 只做 JSON 编码 + 内存队列入队,不再执行任何阻塞 stdout I/O。
  2. buffer 同时按条目数(默认 256)和内存(默认 2 MiB)有界;高频 sample 是实时快照,可在背压时丢弃/合并旧 sample,raw event 与最终报告仍独立落盘,不受 wire sample drop 影响。
  3. hello / ready / capabilities / control_rejected / stop_requested / capture_stopped / finalizer_progress / report_sealed / stopped / error 等控制/生命周期记录不可丢,并保持入队顺序。
  4. 相邻 pending sample 会 coalesce 为最新快照,避免 Host 恢复读取后重放长时间过期 UI sample。
  5. capture_stopped 后主动清除尚未写出的旧 sample,使停止与 finalization 控制记录不被实时快照排队拖延。
  6. writer pipe 错误只标记 sink failed,并继续清空内存队列;不能反向冻结 capture loop。
  7. 最终 stopped 新增 wireDroppedSampleCount / wireMaxBufferedCount / wireMaxBufferedBytes,供下一轮 E4 直接量化 host wire 背压。

E2 验证 ​

  • _WireOutput 专项:15/15 PASS;包含 writer 被故意阻塞时 caller 快速返回、sample coalesce、控制记录不丢、asyncio heartbeat 不被饿死。
  • Display / FrameTime / ActivityTrace 相关专项:118/118 PASS。
  • Sidecar Python 全量:578/578 PASS(首次全量出现 1 项 Startup 时间敏感断言失败;同一项独立连续 5/5 PASS,第二次全量 578/578 PASS,判定为既有时序 flake,非本修复回归)。

下一轮 E4 验收(Build 65) ​

优先只跑一轮 30~60 秒 Display 动态场景,验收以下硬门禁:

text
display-acquisition-census.json.census.subscription
  deliveredEventCount  ~= frameLifetimeMatchedCount
  consumedEventCount   ~= deliveredEventCount
  undrainedAtClose      ~= 0
  droppedEventCount     = 0

metrics.csv
  FPS                   连续有值,不再 0/N 全 missing
  FrameTime             连续有值
  P95 / Jitter          达到 warmup 阈值后有值

wire stopped record
  wireDroppedSampleCount 允许 > 0(表示 UI 快照在 host 背压下被诚实丢弃)
  但 raw event / frame census / report coverage 不得因此缺失

若该轮满足 consumed/delivered >= 99% 且 undrainedAtClose <= 1,即可关闭“stdout wire 阻塞导致 Display consumer starvation”这一根因;随后再做 Startup+Display 与静态/动态切换两场回归。当前状态:代码修复完成 E2,等待 Build 65 E4。


Validation Update · Build 65 (2026-09-18) ​

  • R8-Fix-3 stdout hypothesis REFUTED as primary cause: Real device Build 65 test proved that adding _WireOutput (asynchronous stdout queue) did not resolve the Display Source drain blockage or restore live FPS/FrameTime.
  • _WireOutput retained as defensive wire decoupling: Wire thread decoupling is retained to protect the event loop against slow JSON-RPC pipe readers, but is not the root cause of the Display performance gap.
  • New primary direction: Source Drain ↔ Durable Writer coupling (R8-Fix-4). ActivityTrace high-frequency events were synchronously blocked by the slow disk persistence chain in SessionWriter.append(). Detailed solution is documented in p4-r8-fix4-display-ingress-decoupling-plan.md.

Perfowl · Performance Observer