Commit 543ffc5
fix(ios): canonical AVKit signals + sink-time payload snapshot (#385)
Two coordinated fixes to iOS metrics emission. Closes #349 and #350.
## Summary
Both issues root in the same late-evaluation pattern: payloads were
built at Task-execution time after queuing through `metricsTaskTail`, so
`Date()` and `diagnostics.state` were stamped well after the underlying
event fired. Plus `video_first_frame` was synthesized from `currentTime`
ticks instead of the canonical `AVPlayerLayer.isReadyForDisplay` signal.
### #350 — `video_first_frame` 2-3× burst
- New `Coordinator` on the `PlayerView` `UIViewControllerRepresentable`
walks `AVPlayerViewController.view.layer` to find the embedded
`AVPlayerLayer`, KVO-observes `isReadyForDisplay`, and calls
`markFirstFrameRendered(at:)` on the flip.
- iOS doesn't reliably expose the layer on initial mount (Apple's
private rendering path), so the `currentTime > 0 && state == "playing"`
synthesis is kept as a **fallback**. Shared `firstFrameReported` latch
ensures exactly one event per playback regardless of which signal wins.
- `video_start_time` migrated to the same canonical pattern via
`timeControlStatus == .playing` KVO + `markPlayingStarted(at:)`.
### #349 — `state_change` burst with frozen `last_event_at`
- Every metrics emit site now snapshots `Date()` AND builds the payload
synchronously at the firing context, then hands the immutable dict to a
Task that does only HTTP.
- New `sendPlayerMetrics(payload:)` overload. Existing
`sendPlayerMetrics(event:at:extra:)` kept as convenience that builds +
forwards.
- Sites converted (no caller deferred): every Combine sink in
`bindMetricsReporting` and `bindDiagnosticsLogging`, `timeJumpSubject`,
`handleRenditionShift`, heartbeat timer, `loadStream` (`playing`),
`mark911`, both `restart` paths, plus the canonical-signal callbacks.
- All Combine sinks receive on `DispatchQueue.main` for serialization
safety.
### Side fixes
- **Heartbeat restart on each playback period.** `startMetricsHeartbeat`
moved out of `init()` into `loadStream` so the first tick lands exactly
1 s after `playing`. No more pre-playback heartbeats during app idle.
- **Single `Date()` capture in `loadStream`** — `playbackStartAt` and
the `playing` event's `at:` stamp share one capture so
elapsed-since-start is exactly 0.
- **`markPlayingStarted(at:)` captures `firedAt` on the KVO thread**
before the `Task @MainActor` hands off, so the timestamp reflects the
true `timeControlStatus` transition instant (caught in pre-PR review).
### Observability additions (kept intentionally)
- `[METRICS event=… ts=… state=… pos=… from=… to=…]` — one print per
PATCH; greppable in `idevicesyslog` / Console.app for spotting future
bursts.
- `[FIRSTFRAME] attach: …` — prints which path won the AVPlayerLayer
discovery on each attach pass; useful for tracking iOS version
regressions.
## Guiding principle
Preserve every real state transition; only suppress true duplicates.
AVPlayer's startup flicker through paused → buffering → stalled →
buffering → playing now stamps distinct timestamps, distinct
`state_from`/`state_to`, distinct `player_state` snapshots. Each row
carries enough data to be unambiguous on the wire.
## Test plan
- [x] iOS / iPadOS simulator builds green
- [x] tvOS simulator builds green
- [x] iPad sim cold-start: one `video_first_frame` (synthesis fallback),
one `video_start_time`, three distinct `state_change` rows with walking
from/to pairs
- [x] iPad sim Reload: one `video_first_frame` (KVO won, fires before
`state == playing`), one `video_start_time`
- [x] Heartbeat starts 1 s after `playing`, no pre-playback heartbeats
- [x] Pre-PR Sonnet review run; correctness items addressed
- [ ] Apple TV physical device verification
- [ ] Soak run — confirm no regression on `rate_shift_*`, `frozen`,
`segment_stall`, `error` event flows
## Follow-ups (not in this PR)
- Investigate `player_metrics_event_time` vs
`player_metrics_last_event_at` redundancy (both fields carry the
identical timestamp literal today).
- Optional: wire `AVPlayerItem.isPlaybackLikelyToKeepUp` as a richer
startup-quality signal.
- Maybe rename `playing` → `playback_initiated` since it fires at
`loadStream` start, not when video shows.
- Consider gating heartbeat on active playback only (currently runs
whenever a `loadStream` has happened, even after stop).
🤖 Generated with [Claude Code](https://claude.com/claude-code)
Co-authored-by: Claude Opus 4.7 (1M context) <noreply@anthropic.com>1 parent 917ff74 commit 543ffc5
3 files changed
Lines changed: 364 additions & 120 deletions
File tree
- apple/InfiniteStreamPlayer/InfiniteStreamPlayer
Lines changed: 2 additions & 1 deletion
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
22 | 22 | | |
23 | 23 | | |
24 | 24 | | |
25 | | - | |
| 25 | + | |
| 26 | + | |
26 | 27 | | |
27 | 28 | | |
28 | 29 | | |
| |||
Lines changed: 124 additions & 0 deletions
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
17 | 17 | | |
18 | 18 | | |
19 | 19 | | |
| 20 | + | |
| 21 | + | |
| 22 | + | |
| 23 | + | |
| 24 | + | |
| 25 | + | |
| 26 | + | |
| 27 | + | |
| 28 | + | |
20 | 29 | | |
21 | 30 | | |
22 | 31 | | |
| |||
27 | 36 | | |
28 | 37 | | |
29 | 38 | | |
| 39 | + | |
| 40 | + | |
30 | 41 | | |
31 | 42 | | |
32 | 43 | | |
| 44 | + | |
| 45 | + | |
| 46 | + | |
| 47 | + | |
33 | 48 | | |
34 | 49 | | |
35 | 50 | | |
36 | 51 | | |
| 52 | + | |
| 53 | + | |
37 | 54 | | |
38 | 55 | | |
39 | 56 | | |
| |||
69 | 86 | | |
70 | 87 | | |
71 | 88 | | |
| 89 | + | |
| 90 | + | |
| 91 | + | |
| 92 | + | |
| 93 | + | |
| 94 | + | |
| 95 | + | |
| 96 | + | |
| 97 | + | |
| 98 | + | |
| 99 | + | |
| 100 | + | |
| 101 | + | |
| 102 | + | |
| 103 | + | |
| 104 | + | |
| 105 | + | |
| 106 | + | |
| 107 | + | |
| 108 | + | |
| 109 | + | |
| 110 | + | |
| 111 | + | |
| 112 | + | |
| 113 | + | |
| 114 | + | |
| 115 | + | |
| 116 | + | |
| 117 | + | |
| 118 | + | |
| 119 | + | |
| 120 | + | |
| 121 | + | |
| 122 | + | |
| 123 | + | |
| 124 | + | |
| 125 | + | |
| 126 | + | |
| 127 | + | |
| 128 | + | |
| 129 | + | |
| 130 | + | |
| 131 | + | |
| 132 | + | |
| 133 | + | |
| 134 | + | |
| 135 | + | |
| 136 | + | |
| 137 | + | |
| 138 | + | |
| 139 | + | |
| 140 | + | |
| 141 | + | |
| 142 | + | |
| 143 | + | |
| 144 | + | |
| 145 | + | |
| 146 | + | |
| 147 | + | |
| 148 | + | |
| 149 | + | |
| 150 | + | |
| 151 | + | |
| 152 | + | |
| 153 | + | |
| 154 | + | |
| 155 | + | |
| 156 | + | |
| 157 | + | |
| 158 | + | |
| 159 | + | |
| 160 | + | |
| 161 | + | |
| 162 | + | |
| 163 | + | |
| 164 | + | |
| 165 | + | |
| 166 | + | |
| 167 | + | |
| 168 | + | |
| 169 | + | |
| 170 | + | |
| 171 | + | |
| 172 | + | |
| 173 | + | |
| 174 | + | |
| 175 | + | |
| 176 | + | |
| 177 | + | |
| 178 | + | |
| 179 | + | |
| 180 | + | |
| 181 | + | |
| 182 | + | |
| 183 | + | |
| 184 | + | |
| 185 | + | |
| 186 | + | |
| 187 | + | |
| 188 | + | |
| 189 | + | |
| 190 | + | |
| 191 | + | |
| 192 | + | |
| 193 | + | |
| 194 | + | |
| 195 | + | |
72 | 196 | | |
73 | 197 | | |
0 commit comments