From 365764fffb9cc4d9e46476925a1a100ecd12e33b Mon Sep 17 00:00:00 2001 From: Markus Fritsche Date: Mon, 4 May 2026 11:39:42 +0000 Subject: [PATCH] Phase 0 amendment: hantro writes zeros, sentinel test cache-buggy MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Re-baselined libva-v4l2-request decode path with kernel-side observability (ftrace v4l2/vb2/dma_fence + dmesg + dynamic_debug) and visual disambiguator (mpv --vo=gpu in operator's live Plasma session). Findings: 1. Kernel reports successful CAPTURE buffer write every frame: ftrace vb2_buf_done shows bytesused=3655712 (full NV12 1920x1088 + hantro tile padding). dmesg completely silent — no hantro/vpu/decode/error/warn messages. 2. Visual disambiguator: mpv --hwdec=vaapi-copy --vo=gpu shows a solid GREEN frame; --hwdec=vaapi --vo=gpu shows solid BLUE. Neither shows the sentinel mid-beige (NV12 Y=0xab,UV=0xab would render cream). Both colors are consistent with the kernel writing all-zero NV12 (Y=0,UV=0 → green via BT.709 limited; same buffer GL-imported as DMA-BUF with different colorspace → blue). 3. Patch 0011 sentinel test has a cache-coherency bug: writes 0xab via cached surface_object->destination_map[0] mmap, never invalidates cache before readback. So the readback always shows the stale sentinel even when kernel DMA-overwrote it with zeros. vaapi-copy and Mesa DMA-BUF GL import correctly invalidate cache and see the real (zero) contents. This corrects the previous Phase 0 verdicts twice in one day: - Original commit f15ba8b ("the 2026-04-26 picture holds") was wrong: clean contract trace, never checked pixel content. - Revised commit e892cea ("kernel produces no decoded pixel output, sentinel survives") was half right: kernel does write, writes zeros, and the sentinel test was reading stale cache. - Now: kernel writes ALL ZEROS to the CAPTURE buffer. Hantro is silently failing the bitstream parse or some control validation. This is consistent with patch 0011's own commit message hypothesis: "All zeros → kernel did write 0x00s (overwriting our sentinel), and the apparent 'no picture' output is the kernel-side decode actually producing zeros (e.g. parser rejected the bitstream)." That hypothesis was right; we just couldn't confirm it via the sentinel test (cache bug) and went down the wrong rabbit hole. Phase 6 direction sharpens substantially. Bug isn't "we can't engage hantro" — it's "hantro engages but its parser produces zeros." Bisect the control submission: VIDIOC_G_EXT_CTRLS readback to verify writes stick, diff against FFmpeg's v4l2_request_h264.c (proven working on hantro), verify SPS completeness, resolve patch 0008's slice_header bit_size open question, dyndbg the hantro module, etc. Phase 1 boolean- correctness criterion needs a working pixel-content check before lock; fix patch 0011's cache sync first. Co-Authored-By: Claude Opus 4.7 (1M context) --- .../2026-05-04-kernel-trace/dmesg.txt | 63 +++++++++ .../2026-05-04-kernel-trace/findings.md | 115 +++++++++++++++ .../2026-05-04-kernel-trace/ftrace.txt | 132 ++++++++++++++++++ .../2026-05-04-kernel-trace/mpv.stderr | 40 ++++++ .../2026-05-04-kernel-trace/mpv.stdout | 107 ++++++++++++++ phase0_findings.md | 38 +++-- 6 files changed, 487 insertions(+), 8 deletions(-) create mode 100644 phase0_evidence/2026-05-04-kernel-trace/dmesg.txt create mode 100644 phase0_evidence/2026-05-04-kernel-trace/findings.md create mode 100644 phase0_evidence/2026-05-04-kernel-trace/ftrace.txt create mode 100644 phase0_evidence/2026-05-04-kernel-trace/mpv.stderr create mode 100644 phase0_evidence/2026-05-04-kernel-trace/mpv.stdout diff --git a/phase0_evidence/2026-05-04-kernel-trace/dmesg.txt b/phase0_evidence/2026-05-04-kernel-trace/dmesg.txt new file mode 100644 index 0000000..57c40c1 --- /dev/null +++ b/phase0_evidence/2026-05-04-kernel-trace/dmesg.txt @@ -0,0 +1,63 @@ +[164409.369147] vb2_common_vm_open: 000000006fee19be, refcount: 1, vma: ffff74093000-ffff74410000 +[164409.369176] vb2_dc_mmap: mapped dma addr 0xffc00000 at 0xffff74093000, size 3657728 +[164409.393936] vb2_common_vm_open: 00000000cd1dc2b0, refcount: 1, vma: ffff6cea0000-ffff6cfa0000 +[164409.393966] vb2_dc_mmap: mapped dma addr 0xffb00000 at 0xffff6cea0000, size 1048576 +[164409.394135] vb2_common_vm_open: 00000000d8648f35, refcount: 1, vma: ffff6cda0000-ffff6cea0000 +[164409.394145] vb2_dc_mmap: mapped dma addr 0xffa00000 at 0xffff6cda0000, size 1048576 +[164409.394289] vb2_common_vm_open: 000000002dc1a0f9, refcount: 1, vma: ffff6cca0000-ffff6cda0000 +[164409.394298] vb2_dc_mmap: mapped dma addr 0xff900000 at 0xffff6cca0000, size 1048576 +[164409.394418] vb2_common_vm_open: 00000000105d46cc, refcount: 1, vma: ffff6c2f0000-ffff6c3f0000 +[164409.394427] vb2_dc_mmap: mapped dma addr 0xff800000 at 0xffff6c2f0000, size 1048576 +[164409.396063] ref_pic_list_p (cur_poc 0f) | +[164409.396089] ref_pic_list_b0 (cur_poc 0f) | +[164409.396095] ref_pic_list_b1 (cur_poc 0f) | +[164409.400272] vb2_common_vm_open: 00000000ee441ba9, refcount: 1, vma: ffff50c23000-ffff50fa0000 +[164409.400303] vb2_dc_mmap: mapped dma addr 0xff400000 at 0xffff50c23000, size 3657728 +[164409.402342] ref_pic_list_p (cur_poc 4f) |0sf| +[164409.402371] ref_pic_list_b0 (cur_poc 4f) |0sf| +[164409.402377] ref_pic_list_b1 (cur_poc 4f) |0sf| +[164409.406415] vb2_common_vm_open: 0000000047100871, refcount: 1, vma: ffff508a6000-ffff50c23000 +[164409.406445] vb2_dc_mmap: mapped dma addr 0xff000000 at 0xffff508a6000, size 3657728 +[164409.408371] ref_pic_list_p (cur_poc 2f) |1sf|0sf| +[164409.408401] ref_pic_list_b0 (cur_poc 2f) |0sf|4sf| +[164409.408407] ref_pic_list_b1 (cur_poc 2f) |4sf|0sf| +[164409.413010] vb2_common_vm_open: 00000000bbb580d1, refcount: 1, vma: ffff50529000-ffff508a6000 +[164409.413039] vb2_dc_mmap: mapped dma addr 0xfec00000 at 0xffff50529000, size 3657728 +[164409.415279] ref_pic_list_p (cur_poc 8f) |1sf|0sf| +[164409.415303] ref_pic_list_b0 (cur_poc 8f) |4sf|0sf| +[164409.415309] ref_pic_list_b1 (cur_poc 8f) |0sf|4sf| +[164409.418795] vb2_common_vm_open: 00000000e1700fb9, refcount: 1, vma: ffff501ac000-ffff50529000 +[164409.418823] vb2_dc_mmap: mapped dma addr 0xfe800000 at 0xffff501ac000, size 3657728 +[164409.420609] ref_pic_list_p (cur_poc 6f) |2sf|1sf| +[164409.420631] ref_pic_list_b0 (cur_poc 6f) |4sf|8sf| +[164409.420636] ref_pic_list_b1 (cur_poc 6f) |8sf|4sf| +[164409.424805] vb2_common_vm_open: 00000000db68d9b2, refcount: 1, vma: ffff33c83000-ffff34000000 +[164409.424835] vb2_dc_mmap: mapped dma addr 0xfe400000 at 0xffff33c83000, size 3657728 +[164409.427075] ref_pic_list_p (cur_poc 12f) |2sf|1sf| +[164409.427101] ref_pic_list_b0 (cur_poc 12f) |8sf|4sf| +[164409.427107] ref_pic_list_b1 (cur_poc 12f) |4sf|8sf| +[164409.431562] vb2_common_vm_open: 00000000fb4ad050, refcount: 1, vma: ffff33906000-ffff33c83000 +[164409.431593] vb2_dc_mmap: mapped dma addr 0xfe000000 at 0xffff33906000, size 3657728 +[164409.432292] ref_pic_list_p (cur_poc 10f) |3sf|2sf| +[164409.432316] ref_pic_list_b0 (cur_poc 10f) |8sf|12sf| +[164409.432322] ref_pic_list_b1 (cur_poc 10f) |12sf|8sf| +[164409.458338] ref_pic_list_p (cur_poc 16f) |3sf|2sf| +[164409.458365] ref_pic_list_b0 (cur_poc 16f) |12sf|8sf| +[164409.458372] ref_pic_list_b1 (cur_poc 16f) |8sf|12sf| +[164409.483681] ref_pic_list_p (cur_poc 14f) |4sf|3sf| +[164409.483708] ref_pic_list_b0 (cur_poc 14f) |12sf|16sf| +[164409.483714] ref_pic_list_b1 (cur_poc 14f) |16sf|12sf| +[164409.508649] ref_pic_list_p (cur_poc 20f) |4sf|3sf| +[164409.508676] ref_pic_list_b0 (cur_poc 20f) |16sf|12sf| +[164409.508682] ref_pic_list_b1 (cur_poc 20f) |12sf|16sf| +[164409.531008] vb2_common_vm_close: 000000006fee19be, refcount: 1, vma: ffff74093000-ffff74410000 +[164409.532091] vb2_common_vm_close: 00000000bbb580d1, refcount: 1, vma: ffff50529000-ffff508a6000 +[164409.533000] vb2_common_vm_close: 00000000db68d9b2, refcount: 1, vma: ffff33c83000-ffff34000000 +[164409.534029] vb2_common_vm_close: 00000000fb4ad050, refcount: 1, vma: ffff33906000-ffff33c83000 +[164409.534924] vb2_common_vm_close: 00000000ee441ba9, refcount: 1, vma: ffff50c23000-ffff50fa0000 +[164409.535973] vb2_common_vm_close: 0000000047100871, refcount: 1, vma: ffff508a6000-ffff50c23000 +[164409.536807] vb2_common_vm_close: 00000000e1700fb9, refcount: 1, vma: ffff501ac000-ffff50529000 +[164409.537645] vb2_common_vm_close: 00000000cd1dc2b0, refcount: 1, vma: ffff6cea0000-ffff6cfa0000 +[164409.538040] vb2_common_vm_close: 00000000d8648f35, refcount: 1, vma: ffff6cda0000-ffff6cea0000 +[164409.538299] vb2_common_vm_close: 000000002dc1a0f9, refcount: 1, vma: ffff6cca0000-ffff6cda0000 +[164409.538570] vb2_common_vm_close: 00000000105d46cc, refcount: 1, vma: ffff6c2f0000-ffff6c3f0000 diff --git a/phase0_evidence/2026-05-04-kernel-trace/findings.md b/phase0_evidence/2026-05-04-kernel-trace/findings.md new file mode 100644 index 0000000..91f53c8 --- /dev/null +++ b/phase0_evidence/2026-05-04-kernel-trace/findings.md @@ -0,0 +1,115 @@ +# Phase 0 deliverable #1 + #4 amendment — kernel-side observability (2026-05-04) + +In-session re-baseline of the libva-v4l2-request decode path with kernel-side observability (ftrace v4l2/vb2/dma_fence events + dmesg + dynamic_debug on v4l2-core/videobuf2 + a real-VO visual disambiguator). Supersedes the userspace-only baseline from `phase0_evidence/2026-05-04/findings.md`. + +## Verdict + +**Hantro accepts the request, reports successful buffer write, and produces all-zero output.** The patch-0011 sentinel test that we previously read as "kernel never wrote the buffer" was misleading due to a cache-coherency bug in the patch's mmap read — kernel DMA-writes the buffer (with zeros), and the cached userspace mmap continues to show the stale sentinel `0xab` until something invalidates the cache. Tools that DO invalidate (vaapi-copy via libva's vaMapBuffer, GL DMA-BUF import via Mesa) see the real contents (zeros). + +**This corrects the previous Phase 0 verdict twice in one day**: +- Original prior commit `f15ba8b`: "the 2026-04-26 picture holds" — wrong, contract trace was clean but pixel content wasn't checked. +- Revised commit `e892cea`: "kernel produces no decoded pixel output, sentinel survives" — half right; kernel does write, but writes zeros, and the sentinel test was reading stale cache. +- Now (this finding): **kernel writes, writes ALL ZEROS, hantro is silently failing the bitstream parse or some control validation.** + +The actual bug surface narrows substantially. Phase 6 work is now bisecting the control-submission / bitstream-parse path, not investigating "why doesn't kernel get called." + +## Evidence + +### ftrace v4l2/vb2 events (132 lines, full mpv vaapi-copy --frames=2 lifecycle) + +For every CAPTURE_MPLANE QBUF/DQBUF cycle, hantro reports: +``` +vb2_buf_done: ... index = 0, type = 9, bytesused = 3655712, timestamp = 1777893356955599000 +``` + +`type=9 = V4L2_BUF_TYPE_VIDEO_CAPTURE_MPLANE`, `bytesused=3655712 = 1920×1088 NV12 + hantro tile padding`. **Kernel signals a successful full-buffer write.** Identical signature for every one of 10 CAPTURE buffers in the trace. + +OUTPUT_MPLANE QBUF for each frame shows realistic per-slice sizes: 6272 (IDR), 108 (small P), 109, 144299 (B-frame size), 117, 122, etc. Real H.264 bitstream, real per-frame sizes. + +`v4l2_dqbuf` reports `bytesused=0` to userspace — that's the multi-plane top-level field which is always 0; the per-plane bytesused lives in `m.planes[]` and isn't traced by these events. + +### dmesg — completely silent + +``` +$ grep -iE "hantro|vpu|decode|fail|error|reject|einval|warn" dmesg.txt | wc -l +0 +``` + +No kernel-side error indication. Hantro doesn't log when its bitstream parser rejects something at this severity tier. (Worth turning on full dynamic_debug for the verisilicon driver in a future probe.) + +### Visual disambiguator — the load-bearing data point + +After the prior commit (`e892cea`) declared the sentinel test conclusive, the operator ran two real-VO tests in their live Plasma 6 Wayland session: + +| Variant | Decode path | Render path | Result | +|---|---|---|---| +| 1 | `--hwdec=vaapi-copy` (vaMapBuffer copies CAPTURE → system memory, then GL upload) | `--vo=gpu` | **Solid GREEN frame** | +| 2 | `--hwdec=vaapi` (CAPTURE stays as DMA-BUF) | `--vo=gpu` (Mesa-imports DMA-BUF as GL texture) | **Solid BLUE frame** | + +Solid green for variant 1 means: NV12 luma=0, chroma=0, BT.709 limited-range expansion → green is the canonical "all-zeros NV12 displayed as RGB" color. Solid blue for variant 2 means same buffer, different colorspace/format interpretation by Mesa's DMA-BUF importer. **Neither shows the sentinel mid-beige (`0xab` on both Y and UV would render as cream/beige), and neither shows real bunny pixels.** + +This rules out "decode produces real pixels" (would be bunny). It rules out "kernel never wrote buffer" (would be sentinel beige in variant 1, since vaapi-copy does its own cache invalidation and would see whatever's in physical memory — and the strace already showed the sentinel was the last thing written there pre-DMA). + +The only remaining explanation: **kernel DMA-writes zeros to the buffer**, which overwrites the sentinel in physical memory. vaapi-copy and Mesa DMA-BUF import both correctly cache-invalidate and see the zeros. Patch 0011's sentinel-readback in libva-v4l2-request's `picture.c::RequestEndPicture` reads from a stale cache view — sees the sentinel that's no longer in physical memory. + +## Cache-coherency bug in patch 0011 — root cause + +Patch 0011 instruments `src/picture.c::RequestEndPicture` to write `0xab × 32` into `surface_object->destination_map[0]` immediately before VIDIOC_QBUF. The mmap pointer was set up by libva-v4l2-request's `surface.c` via `mmap(MAP_SHARED, V4L2_MEMORY_MMAP fd)`. On hantro/RK3568 (CMA-backed, dma-contig allocator), this mmap is **CACHED by default unless the queue requests V4L2_MEMORY_DMABUF or the driver applies non-cached attrs**. After QBUF → kernel DMA write → DQBUF, the userspace cached view is stale relative to physical memory. + +Patch 0010's hex-dump (which reads back the buffer for the DEBUG output) reads from the same cached mmap — which is why the dump consistently shows `ab ab ab ab ...`: the cache line containing the first 32 bytes was filled by the userspace 0xab write and never invalidated. + +The fix for the test (so it stops misleading future probes): +- `msync(p, N, MS_SYNC | MS_INVALIDATE)` after DQBUF before reading +- OR call DMA-BUF cache sync via `DMA_BUF_IOCTL_SYNC` if using EXPBUF'd fd +- OR allocate via V4L2_MEMORY_DMABUF instead of MMAP (changes the ownership model — different fix) +- OR use VIDIOC_PREPARE_BUF with cache-flush flags (not supported by hantro M2M IIUC) + +The fix doesn't matter for production — patches 0010/0011 are explicitly DEBUG-only (PKGBUILD comments say "Removed before upstream submission"). What matters is **the test was load-bearing for diagnosis and was wrong**. The whole cascade of "decode is broken" → "we need kernel observability" → this finding came from trusting it. + +## What hantro is actually doing (and not doing) + +Hantro's H.264 frontend likely does this for our requests: +1. Accepts the V4L2_BUF + REQUEST_FD pair +2. Reads the V4L2_CTRL_TYPE_H264_* controls from the request +3. Validates them; if validation fails silently, falls through +4. Parses the OUTPUT slice +5. If parse fails (e.g. SPS/PPS mismatch with slice data, scaling matrix shape wrong, decode_mode wrong), the hardware pipeline still runs but produces zeros — because the decode "kernel" (the actual silicon pipeline) gets garbage matrix coefficients or stops at slice header +6. `vb2_set_plane_payload(buf, 0, full_buffer_size)` is called regardless — explaining the bytesused=3655712 signal even though no real pixels were written + +This is consistent with what patch 0011's commit message anticipated: +> All zeros → kernel did write 0x00s (overwriting our sentinel), and the apparent "no picture" output is the kernel-side decode actually producing zeros (e.g. parser rejected the bitstream). + +That hypothesis was **right**; we just couldn't confirm it via the sentinel test (cache bug) and went down the wrong rabbit hole. + +## Phase 6 priority list (substantially narrowed) + +The bug isn't "we can't engage hantro." The bug is "hantro engages but its parser produces zeros." Bisect the control submission: + +1. **Use `VIDIOC_G_EXT_CTRLS` to read controls back from the request fd before QUEUE.** Compare against what `0008-h264-fill-decode-params-from-vaapi.patch` populated. Any discrepancy = our writes aren't sticking. +2. **Compare the per-frame control set against FFmpeg's `v4l2_request_h264.c`** (proven working on hantro, per Bootlin's downstream branch `v4l2-request-n8.1`). Diff: which fields does FFmpeg set that we don't? +3. **Verify SPS submission:** the V4L2_CTRL_TYPE_H264_SPS control needs the full SPS struct. Patch 0013/0018 set level_idc; verify other SPS fields (`profile_idc`, `seq_parameter_set_id`, `log2_max_frame_num_minus4`, `pic_order_cnt_type`, `log2_max_pic_order_cnt_lsb_minus4`, `max_num_ref_frames`, etc.) — these come from VAAPI's `VAPictureParameterBufferH264` not directly, so we need to derive them from the bitstream or rely on VAAPI passing them. +4. **DECODE_PARAMS bit_size fields** (patch 0008's open question, never resolved): if hantro uses these for slice header parsing in FRAME_BASED mode, our zeros could trigger silent reject. FFmpeg sets these by parsing the slice header bit-precisely. +5. **POC sentinel** — re-run with VIDIOC_G_EXT_CTRLS readback after patch-0015's strip to confirm the values reach V4L2 as 0/0, not 65536/65536. +6. **`reference_ts` for the IDR frame**: even though IDRs have no references, hantro may still validate the field. Should be 0 / monotonic from frame 0. + +## Next observable I should add to the rig + +For the next decode probe: +- Enable `dyndbg="file drivers/media/platform/verisilicon/* +pmflt"` on the hantro module to surface any compiled-in `dev_dbg` calls. +- (If module reload is acceptable) reload hantro with `dyndbg` set at module-insert time. +- Add ftrace function-graph for `hantro_*` symbols to see the kernel decode path. +- Add a v4l2-ctl based reproducer (smaller and easier to instrument than mpv): feed bbb_h264.h264 (Annex B raw) directly via `v4l2-ctl --stream-out-mmap` — but the request-API shape makes this awkward. May need to write a small C reproducer. + +## Phase 0 status (re-revised) + +- **#1 Re-verify failure-mode finding** — ✗ kernel side completes successfully but produces zero-pixel output. Bitstream parser silently fails. Original 2026-04-26 STUDY claim was wrong at the pixel-content layer. +- **#2 Step 1 reconciliation** — ✓ done in commit `74b3793`. +- **#3 Firefox engagement** — ✓ engages libva in live session; same zero-pixel decode failure as mpv. Falls back to SW after frame 0. +- **#4 Phase 0 baseline anchor** — partial: userspace contract trace ✓, kernel-side ftrace ✓ (this run), but the patch-0011 sentinel test we relied on for pixel-content verification is buggy. **Need to fix or replace the pixel-content check** before Phase 1 lock. + +## Artifacts + +- `ftrace.txt` — 132 lines, v4l2/vb2/dma_fence events for the mpv vaapi-copy --frames=2 run +- `dmesg.txt` — 63 lines, no hantro/vpu/decode/error/warn messages +- `mpv.stderr` — 40 lines, the .so DEBUG dumps (10 sentinel-survivor CAPTURE reads, all of which we now know are cache-stale) +- `mpv.stdout` — 107 lines, normal mpv playback log (`Using hardware decoding (vaapi-copy).`) diff --git a/phase0_evidence/2026-05-04-kernel-trace/ftrace.txt b/phase0_evidence/2026-05-04-kernel-trace/ftrace.txt new file mode 100644 index 0000000..b489061 --- /dev/null +++ b/phase0_evidence/2026-05-04-kernel-trace/ftrace.txt @@ -0,0 +1,132 @@ +# tracer: nop +# +# entries-in-buffer/entries-written: 120/120 #P:4 +# +# _-----=> irqs-off/BH-disabled +# / _----=> need-resched +# | / _---=> hardirq/softirq +# || / _--=> preempt-depth +# ||| / _-=> migrate-disable +# |||| / delay +# TASK-PID CPU# ||||| TIMESTAMP FUNCTION +# | | | ||||| | | + av:h264:df0-148779 [001] ..... 164409.395851: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 0, type = 9, bytesused = 3655712, timestamp = 0 + av:h264:df0-148779 [001] ..... 164409.395858: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 0, type = 9, bytesused = 3655712, timestamp = 0 + av:h264:df0-148779 [001] ..... 164409.395869: v4l2_qbuf: minor = 1, index = 0, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|QUEUED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = ANY, timestamp = 0, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df0-148779 [001] ..... 164409.395920: v4l2_qbuf: minor = 1, index = 0, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800080, field = NONE, timestamp = 1777893356955599000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df0-148779 [001] ..... 164409.395934: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 0, type = 10, bytesused = 6272, timestamp = 1777893356955599000 + av:h264:df0-148779 [001] ..... 164409.395935: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 0, type = 10, bytesused = 6272, timestamp = 1777893356955599000 + systemd-journal-2348 [000] d.h1. 164409.396156: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 0, type = 9, bytesused = 3655712, timestamp = 1777893356955599000 + systemd-journal-2348 [000] d.h1. 164409.396200: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 0, type = 10, bytesused = 6272, timestamp = 1777893356955599000 + av:h264:df0-148779 [001] ..... 164409.396268: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 0, type = 10, bytesused = 6272, timestamp = 1777893356955599000 + av:h264:df0-148779 [001] ..... 164409.396273: v4l2_dqbuf: minor = 1, index = 0, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800000, field = NONE, timestamp = 1777893356955599000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df0-148779 [001] ..... 164409.396279: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 0, type = 9, bytesused = 3655712, timestamp = 1777893356955599000 + av:h264:df0-148779 [001] ..... 164409.396281: v4l2_dqbuf: minor = 1, index = 0, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = NONE, timestamp = 1777893356955599000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df1-148780 [003] ..... 164409.402228: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 1, type = 9, bytesused = 3655712, timestamp = 0 + av:h264:df1-148780 [003] ..... 164409.402236: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 1, type = 9, bytesused = 3655712, timestamp = 0 + av:h264:df1-148780 [003] ..... 164409.402246: v4l2_qbuf: minor = 1, index = 1, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|QUEUED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = ANY, timestamp = 0, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df1-148780 [003] ..... 164409.402285: v4l2_qbuf: minor = 1, index = 1, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800080, field = NONE, timestamp = 1777893356962057000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df1-148780 [003] ..... 164409.402297: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 1, type = 10, bytesused = 108, timestamp = 1777893356962057000 + av:h264:df1-148780 [003] ..... 164409.402298: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 1, type = 10, bytesused = 108, timestamp = 1777893356962057000 + -0 [000] d.h2. 164409.402441: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 1, type = 9, bytesused = 3655712, timestamp = 1777893356962057000 + -0 [000] d.h2. 164409.402495: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 1, type = 10, bytesused = 108, timestamp = 1777893356962057000 + av:h264:df1-148780 [003] ..... 164409.402552: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 1, type = 10, bytesused = 108, timestamp = 1777893356962057000 + av:h264:df1-148780 [003] ..... 164409.402556: v4l2_dqbuf: minor = 1, index = 1, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800000, field = NONE, timestamp = 1777893356962057000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 1 + av:h264:df1-148780 [003] ..... 164409.402561: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 1, type = 9, bytesused = 3655712, timestamp = 1777893356962057000 + av:h264:df1-148780 [003] ..... 164409.402562: v4l2_dqbuf: minor = 1, index = 1, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = NONE, timestamp = 1777893356962057000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 1 + av:h264:df2-148781 [001] ..... 164409.408246: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 2, type = 9, bytesused = 3655712, timestamp = 0 + av:h264:df2-148781 [001] ..... 164409.408254: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 2, type = 9, bytesused = 3655712, timestamp = 0 + av:h264:df2-148781 [001] ..... 164409.408266: v4l2_qbuf: minor = 1, index = 2, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|QUEUED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = ANY, timestamp = 0, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df2-148781 [001] ..... 164409.408312: v4l2_qbuf: minor = 1, index = 2, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800080, field = NONE, timestamp = 1777893356968082000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df2-148781 [001] ..... 164409.408324: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 2, type = 10, bytesused = 109, timestamp = 1777893356968082000 + av:h264:df2-148781 [001] ..... 164409.408324: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 2, type = 10, bytesused = 109, timestamp = 1777893356968082000 + -0 [000] d.h2. 164409.408476: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 2, type = 9, bytesused = 3655712, timestamp = 1777893356968082000 + -0 [000] d.h2. 164409.408527: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 2, type = 10, bytesused = 109, timestamp = 1777893356968082000 + av:h264:df2-148781 [001] ..... 164409.408585: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 2, type = 10, bytesused = 109, timestamp = 1777893356968082000 + av:h264:df2-148781 [001] ..... 164409.408588: v4l2_dqbuf: minor = 1, index = 2, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800000, field = NONE, timestamp = 1777893356968082000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 2 + av:h264:df2-148781 [001] ..... 164409.408595: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 2, type = 9, bytesused = 3655712, timestamp = 1777893356968082000 + av:h264:df2-148781 [001] ..... 164409.408596: v4l2_dqbuf: minor = 1, index = 2, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = NONE, timestamp = 1777893356968082000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 2 + av:h264:df3-148782 [003] ..... 164409.415179: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 3, type = 9, bytesused = 3655712, timestamp = 0 + av:h264:df3-148782 [003] ..... 164409.415184: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 3, type = 9, bytesused = 3655712, timestamp = 0 + av:h264:df3-148782 [003] ..... 164409.415193: v4l2_qbuf: minor = 1, index = 3, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|QUEUED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = ANY, timestamp = 0, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df3-148782 [003] ..... 164409.415233: v4l2_qbuf: minor = 1, index = 3, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800080, field = NONE, timestamp = 1777893356975051000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df3-148782 [003] ..... 164409.415242: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 3, type = 10, bytesused = 144299, timestamp = 1777893356975051000 + av:h264:df3-148782 [003] ..... 164409.415243: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 3, type = 10, bytesused = 144299, timestamp = 1777893356975051000 + -0 [000] d.h2. 164409.415359: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 3, type = 9, bytesused = 3655712, timestamp = 1777893356975051000 + -0 [000] d.h2. 164409.415385: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 3, type = 10, bytesused = 144299, timestamp = 1777893356975051000 + av:h264:df3-148782 [003] ..... 164409.415437: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 3, type = 10, bytesused = 144299, timestamp = 1777893356975051000 + av:h264:df3-148782 [003] ..... 164409.415440: v4l2_dqbuf: minor = 1, index = 3, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800000, field = NONE, timestamp = 1777893356975051000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 3 + av:h264:df3-148782 [003] ..... 164409.415446: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 3, type = 9, bytesused = 3655712, timestamp = 1777893356975051000 + av:h264:df3-148782 [003] ..... 164409.415447: v4l2_dqbuf: minor = 1, index = 3, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = NONE, timestamp = 1777893356975051000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 3 + av:h264:df0-148779 [001] ..... 164409.420516: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 4, type = 9, bytesused = 3655712, timestamp = 0 + av:h264:df0-148779 [001] ..... 164409.420521: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 4, type = 9, bytesused = 3655712, timestamp = 0 + av:h264:df0-148779 [001] ..... 164409.420530: v4l2_qbuf: minor = 1, index = 4, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|QUEUED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = ANY, timestamp = 0, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df0-148779 [001] ..... 164409.420565: v4l2_qbuf: minor = 1, index = 0, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800080, field = NONE, timestamp = 1777893356980390000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df0-148779 [001] ..... 164409.420574: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 0, type = 10, bytesused = 248054, timestamp = 1777893356980390000 + av:h264:df0-148779 [001] ..... 164409.420575: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 0, type = 10, bytesused = 248054, timestamp = 1777893356980390000 + -0 [000] d.h2. 164409.420687: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 4, type = 9, bytesused = 3655712, timestamp = 1777893356980390000 + -0 [000] d.h2. 164409.420713: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 0, type = 10, bytesused = 248054, timestamp = 1777893356980390000 + av:h264:df0-148779 [001] ..... 164409.420806: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 0, type = 10, bytesused = 248054, timestamp = 1777893356980390000 + av:h264:df0-148779 [001] ..... 164409.420810: v4l2_dqbuf: minor = 1, index = 0, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800000, field = NONE, timestamp = 1777893356980390000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 4 + av:h264:df0-148779 [001] ..... 164409.420815: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 4, type = 9, bytesused = 3655712, timestamp = 1777893356980390000 + av:h264:df0-148779 [001] ..... 164409.420816: v4l2_dqbuf: minor = 1, index = 4, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = NONE, timestamp = 1777893356980390000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 4 + av:h264:df1-148780 [002] ..... 164409.426981: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 5, type = 9, bytesused = 3655712, timestamp = 0 + av:h264:df1-148780 [002] ..... 164409.426987: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 5, type = 9, bytesused = 3655712, timestamp = 0 + av:h264:df1-148780 [002] ..... 164409.426995: v4l2_qbuf: minor = 1, index = 5, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|QUEUED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = ANY, timestamp = 0, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df1-148780 [002] ..... 164409.427030: v4l2_qbuf: minor = 1, index = 1, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800080, field = NONE, timestamp = 1777893356986851000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df1-148780 [002] ..... 164409.427039: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 1, type = 10, bytesused = 95876, timestamp = 1777893356986851000 + av:h264:df1-148780 [002] ..... 164409.427040: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 1, type = 10, bytesused = 95876, timestamp = 1777893356986851000 + mpv-148764 [000] d.h1. 164409.427153: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 5, type = 9, bytesused = 3655712, timestamp = 1777893356986851000 + mpv-148764 [000] d.h1. 164409.427184: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 1, type = 10, bytesused = 95876, timestamp = 1777893356986851000 + av:h264:df1-148780 [002] ..... 164409.427230: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 1, type = 10, bytesused = 95876, timestamp = 1777893356986851000 + av:h264:df1-148780 [002] ..... 164409.427233: v4l2_dqbuf: minor = 1, index = 1, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800000, field = NONE, timestamp = 1777893356986851000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 5 + av:h264:df1-148780 [002] ..... 164409.427239: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 5, type = 9, bytesused = 3655712, timestamp = 1777893356986851000 + av:h264:df1-148780 [002] ..... 164409.427240: v4l2_dqbuf: minor = 1, index = 5, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = NONE, timestamp = 1777893356986851000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 5 + av:h264:df2-148781 [001] ..... 164409.432195: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 6, type = 9, bytesused = 3655712, timestamp = 0 + av:h264:df2-148781 [001] ..... 164409.432201: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 6, type = 9, bytesused = 3655712, timestamp = 0 + av:h264:df2-148781 [001] ..... 164409.432210: v4l2_qbuf: minor = 1, index = 6, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|QUEUED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = ANY, timestamp = 0, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df2-148781 [001] ..... 164409.432245: v4l2_qbuf: minor = 1, index = 2, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800080, field = NONE, timestamp = 1777893356992059000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df2-148781 [001] ..... 164409.432255: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 2, type = 10, bytesused = 49777, timestamp = 1777893356992059000 + av:h264:df2-148781 [001] ..... 164409.432256: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 2, type = 10, bytesused = 49777, timestamp = 1777893356992059000 + mpv-148764 [000] d.h1. 164409.432371: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 6, type = 9, bytesused = 3655712, timestamp = 1777893356992059000 + mpv-148764 [000] d.h1. 164409.432423: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 2, type = 10, bytesused = 49777, timestamp = 1777893356992059000 + av:h264:df2-148781 [001] ..... 164409.432483: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 2, type = 10, bytesused = 49777, timestamp = 1777893356992059000 + av:h264:df2-148781 [001] ..... 164409.432486: v4l2_dqbuf: minor = 1, index = 2, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800000, field = NONE, timestamp = 1777893356992059000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 6 + av:h264:df2-148781 [001] ..... 164409.432492: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 6, type = 9, bytesused = 3655712, timestamp = 1777893356992059000 + av:h264:df2-148781 [001] ..... 164409.432493: v4l2_dqbuf: minor = 1, index = 6, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = NONE, timestamp = 1777893356992059000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 6 + av:h264:df3-148782 [001] ..... 164409.458237: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 0, type = 9, bytesused = 3655712, timestamp = 1777893356955599000 + av:h264:df3-148782 [001] ..... 164409.458243: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 0, type = 9, bytesused = 3655712, timestamp = 1777893356955599000 + av:h264:df3-148782 [001] ..... 164409.458253: v4l2_qbuf: minor = 1, index = 0, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|QUEUED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = NONE, timestamp = 1777893356955599000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df3-148782 [001] ..... 164409.458289: v4l2_qbuf: minor = 1, index = 3, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800080, field = NONE, timestamp = 1777893357018098000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df3-148782 [001] ..... 164409.458300: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 3, type = 10, bytesused = 60348, timestamp = 1777893357018098000 + av:h264:df3-148782 [001] ..... 164409.458301: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 3, type = 10, bytesused = 60348, timestamp = 1777893357018098000 + mpv-148764 [000] d.h1. 164409.458420: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 0, type = 9, bytesused = 3655712, timestamp = 1777893357018098000 + mpv-148764 [000] d.h1. 164409.458446: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 3, type = 10, bytesused = 60348, timestamp = 1777893357018098000 + av:h264:df3-148782 [001] ..... 164409.458517: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 3, type = 10, bytesused = 60348, timestamp = 1777893357018098000 + av:h264:df3-148782 [001] ..... 164409.458521: v4l2_dqbuf: minor = 1, index = 3, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800000, field = NONE, timestamp = 1777893357018098000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 7 + av:h264:df3-148782 [001] ..... 164409.458526: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 0, type = 9, bytesused = 3655712, timestamp = 1777893357018098000 + av:h264:df3-148782 [001] ..... 164409.458528: v4l2_dqbuf: minor = 1, index = 0, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = NONE, timestamp = 1777893357018098000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 7 + av:h264:df0-148779 [003] ..... 164409.483579: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 2, type = 9, bytesused = 3655712, timestamp = 1777893356968082000 + av:h264:df0-148779 [003] ..... 164409.483584: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 2, type = 9, bytesused = 3655712, timestamp = 1777893356968082000 + av:h264:df0-148779 [003] ..... 164409.483593: v4l2_qbuf: minor = 1, index = 2, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|QUEUED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = NONE, timestamp = 1777893356968082000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df0-148779 [003] ..... 164409.483630: v4l2_qbuf: minor = 1, index = 0, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800080, field = NONE, timestamp = 1777893357043499000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df0-148779 [003] ..... 164409.483639: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 0, type = 10, bytesused = 9557, timestamp = 1777893357043499000 + av:h264:df0-148779 [003] ..... 164409.483641: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 0, type = 10, bytesused = 9557, timestamp = 1777893357043499000 + systemd-journal-2348 [000] d.h1. 164409.483817: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 2, type = 9, bytesused = 3655712, timestamp = 1777893357043499000 + systemd-journal-2348 [000] d.h1. 164409.483824: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 0, type = 10, bytesused = 9557, timestamp = 1777893357043499000 + av:h264:df0-148779 [003] ..... 164409.483877: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 0, type = 10, bytesused = 9557, timestamp = 1777893357043499000 + av:h264:df0-148779 [003] ..... 164409.483881: v4l2_dqbuf: minor = 1, index = 0, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800000, field = NONE, timestamp = 1777893357043499000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 8 + av:h264:df0-148779 [003] ..... 164409.483887: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 2, type = 9, bytesused = 3655712, timestamp = 1777893357043499000 + av:h264:df0-148779 [003] ..... 164409.483888: v4l2_dqbuf: minor = 1, index = 2, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = NONE, timestamp = 1777893357043499000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 8 + av:h264:df1-148780 [003] ..... 164409.508537: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 1, type = 9, bytesused = 3655712, timestamp = 1777893356962057000 + av:h264:df1-148780 [003] ..... 164409.508543: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 1, type = 9, bytesused = 3655712, timestamp = 1777893356962057000 + av:h264:df1-148780 [003] ..... 164409.508552: v4l2_qbuf: minor = 1, index = 1, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|QUEUED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = NONE, timestamp = 1777893356962057000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df1-148780 [003] ..... 164409.508602: v4l2_qbuf: minor = 1, index = 1, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800080, field = NONE, timestamp = 1777893357067976000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 0 + av:h264:df1-148780 [003] ..... 164409.508614: vb2_qbuf: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 1, type = 10, bytesused = 59825, timestamp = 1777893357067976000 + av:h264:df1-148780 [003] ..... 164409.508615: vb2_buf_queue: owner = 0000000000000000, queued = 1, owned_by_drv = 1, index = 1, type = 10, bytesused = 59825, timestamp = 1777893357067976000 + -0 [000] d.h2. 164409.508726: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 1, type = 9, bytesused = 3655712, timestamp = 1777893357067976000 + -0 [000] d.h2. 164409.508730: vb2_buf_done: owner = 0000000000000000, queued = 1, owned_by_drv = 0, index = 1, type = 10, bytesused = 59825, timestamp = 1777893357067976000 + av:h264:df1-148780 [003] ..... 164409.508783: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 1, type = 10, bytesused = 59825, timestamp = 1777893357067976000 + av:h264:df1-148780 [003] ..... 164409.508961: v4l2_dqbuf: minor = 1, index = 1, type = VIDEO_OUTPUT_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY|0x800000, field = NONE, timestamp = 1777893357067976000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 9 + av:h264:df1-148780 [003] ..... 164409.508973: vb2_dqbuf: owner = 0000000000000000, queued = 0, owned_by_drv = 0, index = 1, type = 9, bytesused = 3655712, timestamp = 1777893357067976000 + av:h264:df1-148780 [003] ..... 164409.508974: v4l2_dqbuf: minor = 1, index = 1, type = VIDEO_CAPTURE_MPLANE, bytesused = 0, flags = MAPPED|TIMESTAMP_UNKNOWN|TIMESTAMP_COPY, field = NONE, timestamp = 1777893357067976000, timecode = { type = 0x0, flags = , frames = 0, seconds = 0, minutes = 0, hours = 0, userbits = { 0 0 0 0 } }, sequence = 9 diff --git a/phase0_evidence/2026-05-04-kernel-trace/mpv.stderr b/phase0_evidence/2026-05-04-kernel-trace/mpv.stderr new file mode 100644 index 0000000..906122a --- /dev/null +++ b/phase0_evidence/2026-05-04-kernel-trace/mpv.stderr @@ -0,0 +1,40 @@ +v4l2-request: VAPictureH264 sizeof=36 CurrPic[0..31]: 00 00 00 04 00 00 00 00 08 00 00 00 00 00 01 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 +v4l2-request: VAPictureH264 CurrPic field reads: picture_id=0x04000000 frame_idx=0 flags=0x8 TopFOC=65536 BottomFOC=65536 frame_num=0 +v4l2-request: OUTPUT[idx=0, len=6272]: 00 00 01 25 b8 20 20 21 44 c5 00 01 57 9b ef be fb ef be fb ef be fb ef be fb ef be fb ef be fb +v4l2-request: CAPTURE[idx=0, plane0]: ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab +v4l2-request: VAPictureH264 sizeof=36 CurrPic[0..31]: 01 00 00 04 01 00 00 00 08 00 00 00 04 00 01 00 04 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 +v4l2-request: VAPictureH264 CurrPic field reads: picture_id=0x04000001 frame_idx=1 flags=0x8 TopFOC=65540 BottomFOC=65540 frame_num=1 +v4l2-request: OUTPUT[idx=1, len=108]: 00 00 01 21 e1 09 00 85 00 3f d8 00 00 01 21 00 7f b8 42 40 21 40 0f f6 00 00 01 21 00 3f ce 10 +v4l2-request: CAPTURE[idx=1, plane0]: ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab +v4l2-request: VAPictureH264 sizeof=36 CurrPic[0..31]: 02 00 00 04 02 00 00 00 00 00 00 00 02 00 01 00 02 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 +v4l2-request: VAPictureH264 CurrPic field reads: picture_id=0x04000002 frame_idx=2 flags=0x0 TopFOC=65538 BottomFOC=65538 frame_num=2 +v4l2-request: OUTPUT[idx=2, len=109]: 00 00 01 01 a8 81 60 10 a0 07 fb 00 00 01 01 00 7f aa 20 58 04 28 01 fe c0 00 00 01 01 00 3f ca +v4l2-request: CAPTURE[idx=2, plane0]: ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab +v4l2-request: VAPictureH264 sizeof=36 CurrPic[0..31]: 03 00 00 04 02 00 00 00 08 00 00 00 08 00 01 00 08 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 +v4l2-request: VAPictureH264 CurrPic field reads: picture_id=0x04000003 frame_idx=2 flags=0x8 TopFOC=65544 BottomFOC=65544 frame_num=2 +v4l2-request: OUTPUT[idx=3, len=144299]: 00 00 01 21 e2 11 00 85 42 b8 58 00 05 57 43 01 19 16 05 c1 95 41 3a 7b a1 9b 3b df d1 68 28 be +v4l2-request: CAPTURE[idx=3, plane0]: ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab +v4l2-request: VAPictureH264 sizeof=36 CurrPic[0..31]: 04 00 00 04 03 00 00 00 00 00 00 00 06 00 01 00 06 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 +v4l2-request: VAPictureH264 CurrPic field reads: picture_id=0x04000004 frame_idx=3 flags=0x0 TopFOC=65542 BottomFOC=65542 frame_num=3 +v4l2-request: OUTPUT[idx=0, len=248054]: 00 00 01 01 a8 c3 60 10 aa c6 47 88 8b 07 23 86 0a 5f 25 25 d0 c8 32 6c c6 c1 83 ae 06 83 8d 04 +v4l2-request: CAPTURE[idx=4, plane0]: ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab +v4l2-request: VAPictureH264 sizeof=36 CurrPic[0..31]: 05 00 00 04 03 00 00 00 08 00 00 00 0c 00 01 00 0c 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 +v4l2-request: VAPictureH264 CurrPic field reads: picture_id=0x04000005 frame_idx=3 flags=0x8 TopFOC=65548 BottomFOC=65548 frame_num=3 +v4l2-request: OUTPUT[idx=1, len=95876]: 00 00 01 21 e3 19 00 85 4d ff ff 71 00 00 22 67 0b ba a0 0d d7 40 27 d0 14 2b 89 10 80 3a 1a 09 +v4l2-request: CAPTURE[idx=5, plane0]: ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab +v4l2-request: VAPictureH264 sizeof=36 CurrPic[0..31]: 06 00 00 04 04 00 00 00 00 00 00 00 0a 00 01 00 0a 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 +v4l2-request: VAPictureH264 CurrPic field reads: picture_id=0x04000006 frame_idx=4 flags=0x0 TopFOC=65546 BottomFOC=65546 frame_num=4 +v4l2-request: OUTPUT[idx=2, len=49777]: 00 00 01 01 a9 05 60 10 a6 18 ff ff bb 5b 24 05 e8 56 2b 76 0a 18 ff 8f 71 df b5 6a ef 60 34 98 +v4l2-request: CAPTURE[idx=6, plane0]: ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab +v4l2-request: VAPictureH264 sizeof=36 CurrPic[0..31]: 00 00 00 04 04 00 00 00 08 00 00 00 10 00 01 00 10 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 +v4l2-request: VAPictureH264 CurrPic field reads: picture_id=0x04000000 frame_idx=4 flags=0x8 TopFOC=65552 BottomFOC=65552 frame_num=4 +v4l2-request: OUTPUT[idx=3, len=60348]: 00 00 01 21 e4 21 00 85 44 e2 80 00 a8 8e 23 c4 78 8f 11 e2 3c 47 88 f1 1e 23 c4 78 8f 11 e2 3c +v4l2-request: CAPTURE[idx=0, plane0]: ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab +v4l2-request: VAPictureH264 sizeof=36 CurrPic[0..31]: 02 00 00 04 05 00 00 00 00 00 00 00 0e 00 01 00 0e 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 +v4l2-request: VAPictureH264 CurrPic field reads: picture_id=0x04000002 frame_idx=5 flags=0x0 TopFOC=65550 BottomFOC=65550 frame_num=5 +v4l2-request: OUTPUT[idx=0, len=9557]: 00 00 01 01 a9 47 60 10 a3 06 f9 43 5e 1a f0 d7 41 af 0d 78 6b c3 5e 1a f0 d7 86 bc 35 e1 af 0d +v4l2-request: CAPTURE[idx=2, plane0]: ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab +v4l2-request: VAPictureH264 sizeof=36 CurrPic[0..31]: 01 00 00 04 05 00 00 00 08 00 00 00 14 00 01 00 14 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 +v4l2-request: VAPictureH264 CurrPic field reads: picture_id=0x04000001 frame_idx=5 flags=0x8 TopFOC=65556 BottomFOC=65556 frame_num=5 +v4l2-request: OUTPUT[idx=1, len=59825]: 00 00 01 21 e5 29 00 85 46 e2 80 00 a6 cd f3 7f ff c3 1d 77 75 7c 6e 28 37 cd ff f9 6b d7 bf 7b +v4l2-request: CAPTURE[idx=1, plane0]: ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab diff --git a/phase0_evidence/2026-05-04-kernel-trace/mpv.stdout b/phase0_evidence/2026-05-04-kernel-trace/mpv.stdout new file mode 100644 index 0000000..c6867fa --- /dev/null +++ b/phase0_evidence/2026-05-04-kernel-trace/mpv.stdout @@ -0,0 +1,107 @@ +[cplayer] Command line options: '--hwdec=vaapi-copy' '--vo=null' '--no-audio' '--frames=2' '--msg-level=all=v' '--no-config' '/home/mfritsche/fourier-test/bbb_1080p30_h264.mp4' +[cplayer] mpv v0.41.0 Copyright © 2000-2025 mpv/MPlayer/mplayer2 projects +[cplayer] built on Feb 14 2026 00:53:08 +[cplayer] libplacebo version: v7.360.1 +[cplayer] FFmpeg version: n8.0.1 (runtime n8.1) +[cplayer] FFmpeg library versions: +[cplayer] libavcodec 62.11.100 (runtime 62.28.100) +[cplayer] libavdevice 62.1.100 (runtime 62.3.100) +[cplayer] libavfilter 11.4.100 (runtime 11.14.100) +[cplayer] libavformat 62.3.100 (runtime 62.12.100) +[cplayer] libavutil 60.8.100 (runtime 60.26.100) +[cplayer] libswresample 6.1.100 (runtime 6.3.100) +[cplayer] libswscale 9.1.100 (runtime 9.5.100) +[cplayer] Configuration: -Db_lto=false -Db_pie=true -Dpython.bytecompile=1 -Dlibmpv=true -Dgl-x11=enabled -Dcaca=disabled -Dcdda=enabled -Ddrm=enabled -Ddvbin=enabled -Ddvdnav=enabled -Dlibarchive=enabled -Dopenal=enabled -Dsdl2-audio=enabled -Dsdl2-video=enabled -Dsdl2-gamepad=enabled -Dprefix=/usr -Dlibexecdir=lib -Dsbindir=bin -Dauto_features=auto -Dbuildtype=plain -Dwrap_mode=nodownload +[cplayer] List of enabled features: alsa build-date cdda cplugins cuda-hwaccel cuda-interop dmabuf-interop-gl dmabuf-wayland drm dvbin dvdnav egl egl-drm egl-wayland egl-x11 ffmpeg ffnvcodec gbm gl gl-x11 glibc-thread-name glob glob-posix gpl iconv jack javascript jpeg lcms2 libarchive libass libavdevice libbluray libdl libplacebo linux-fstatfs luajit memfd-create memrchr openal pipewire posix posix-shm ppoll pthread-condattr-setclock pulse rubberband rubberband-3 sdl2-audio sdl2-gamepad sdl2-video sixel sndio sndio-1-9 uchardet vaapi vaapi-drm vaapi-wayland vaapi-x11 vapoursynth vdpau vdpau-gl-x11 vector vk-khr-display vt.h vulkan wayland wayland-protocols-1-32 wayland-protocols-1-38 wayland-protocols-1-39 wayland-protocols-1-41 wayland-protocols-1-44 wayland-protocols-1-47 x11 x11-clipboard xv zimg zimg-st428 zlib +[cplayer] Setting option 'hwdec' = 'vaapi-copy' (flags = 8) +[cplayer] Setting option 'vo' = 'null' (flags = 8) +[cplayer] Setting option 'audio' = 'no' (flags = 8) +[cplayer] Setting option 'frames' = '2' (flags = 8) +[cplayer] Setting option 'msg-level' = 'all=v' (flags = 8) +[cplayer] Setting option 'config' = 'no' (flags = 8) +[clipboard] Initialized vo clipboard backend. +[cplayer] Waiting for scripts... +[cplayer] Set property: user-data/osc/visibility="auto" -> 1 +[cplayer] Set property: user-data/osc/margins={"l":0,"t":0,"b":0,"r":0} -> 1 +[cplayer] Done loading scripts. +[cplayer] Running hook: auto_profiles/on_before_start_file +[cplayer] Failed sending hook command auto_profiles/on_before_start_file. Removing hook. +[cplayer] Running hook: auto_profiles/on_load +[cplayer] Failed sending hook command auto_profiles/on_load. Removing hook. +[cplayer] Running hook: ytdl_hook/on_load +[cplayer] Running hook: ytdl_hook/on_load +[ytdl_hook] playlist hook +[ifo_dvdnav] Opening /home/mfritsche/fourier-test/bbb_1080p30_h264.mp4 +[bdmv/bluray] Opening /home/mfritsche/fourier-test/bbb_1080p30_h264.mp4 +[cplayer] Set property: user-data/osc/margins={"l":0,"t":0,"b":0,"r":0} -> 1 +[file] Opening /home/mfritsche/fourier-test/bbb_1080p30_h264.mp4 +[demux] Trying demuxers for level=normal. +[cplayer] Set property: user-data/osc/margins={"l":0,"t":0,"b":0,"r":0} -> 1 +[osd/libass] libass API version: 0x1704000 +[osd/libass] libass source: commit: 0.17.4-0-gbbb3c7f1570a4a021e52683f3fbdf74fe492ae84 +[osd/libass] Shaper: FriBidi 1.0.16 (SIMPLE) HarfBuzz-ng 14.2.0 (COMPLEX) +[osd/libass] Setting up fonts... +[lavf] Found 'mov,mp4,m4a,3gp,3g2,mj2' at score=100 size=2048. +[file] stream level seek from 131072 to 724711446 +[file] stream level seek from 725125156 to 48 +[file] stream level seek from 131120 to 725125156 +[demux] Detected file format: mov,mp4,m4a,3gp,3g2,mj2 (libavformat) +[cplayer] Opening done: /home/mfritsche/fourier-test/bbb_1080p30_h264.mp4 +[osd/libass] Using font provider fontconfig +[osd/libass] Done. +[find_files] Loading external files in /home/mfritsche/fourier-test/ +[cplayer] Running hook: auto_profiles/on_preloaded +[cplayer] Failed sending hook command auto_profiles/on_preloaded. Removing hook. +[cplayer] Running hook: ytdl_hook/on_preloaded +[lavf] select track 0 +● Video --vid=1 --vlang=eng (h264 1920x1080 24 fps) [default] +○ Audio --aid=1 --alang=eng (aac 6ch 48000 Hz 438 kbps) [default] +[vd] Container reported FPS: 24.000000 +[vd] Codec list: +[vd] h264 - H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10 +[vd] h264_v4l2m2m (h264) - V4L2 mem2mem H.264 decoder wrapper +[vd] h264_amf (h264) - H264 AMD AMF video decoder +[vd] Opening decoder h264 +[vd] Looking at hwdec h264-vaapi-copy... +[vaapi] libva: VA-API version 1.23.0 +[vaapi] libva: User environment variable requested driver 'v4l2_request' +[vaapi] libva: Trying to open /usr/lib/dri/v4l2_request_drv_video.so +[vaapi] libva: Found init function __vaDriverInit_1_23 +[vaapi] libva: va_openDriver() returns 0 +[vaapi] Initialized VAAPI: version 1.23 +[vd] Trying hardware decoding via h264-vaapi-copy. +[vd] Requesting 4 threads for decoding. +[vd] Selected decoder: h264 - H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10 +[vf] User filter list: +[vf] (empty) +[cplayer] Starting playback... +[file] stream level seek from 725125156 to 52 +[vd] Pixel formats supported by decoder: vdpau vulkan drm_prime vaapi yuv420p +[vd] Codec profile: Main (0x4d) +[vd] Requesting pixfmt 'vaapi' from decoder. +Using hardware decoding (vaapi-copy). +[vd] Decoder format: 1920x1080 [0:1] nv12 bt.709/bt.709/bt.1886/limited/auto CL=uhd crop=1920x1080+0+0 A=none +[vf] [in] 1920x1080 nv12 bt.709/bt.709/bt.1886/limited/display CL=uhd crop=1920x1080+0+0 A=none +[vf] [userdeint] 1920x1080 nv12 bt.709/bt.709/bt.1886/limited/display CL=uhd crop=1920x1080+0+0 A=none +[vf] [userdeint] (disabled) +[vf] [autovflip] 1920x1080 nv12 bt.709/bt.709/bt.1886/limited/display CL=uhd crop=1920x1080+0+0 A=none +[vf] [autovflip] (disabled) +[vf] [autorotate] 1920x1080 nv12 bt.709/bt.709/bt.1886/limited/display CL=uhd crop=1920x1080+0+0 A=none +[vf] [autorotate] (disabled) +[vf] [convert] 1920x1080 nv12 bt.709/bt.709/bt.1886/limited/display CL=uhd crop=1920x1080+0+0 A=none +[vf] [convert] (disabled) +[vf] [out] 1920x1080 nv12 bt.709/bt.709/bt.1886/limited/display CL=uhd crop=1920x1080+0+0 A=none +VO: [null] 1920x1080 nv12 +[cplayer] VO: Description: Null video output +[vo/null] reconfig to 1920x1080 nv12 bt.709/bt.709/bt.1886/limited/display CL=uhd crop=1920x1080+0+0 A=none +[cplayer] first video frame after restart shown +[cplayer] playback restart complete @ 0.000000, audio=eof, video=playing +V: 00:00:00 / 00:09:56 (0%) +[cplayer] EOF code: 1 +V: 00:00:00 / 00:09:56 (0%) +[vf] dropping frame due to pin disconnect +V: 00:00:00 / 00:09:56 (0%) +[cplayer] finished playback, success (reason 0) +[cplayer] Running hook: ytdl_hook/on_after_end_file +Exiting... (End of file) +[cplayer] Set property: user-data/osc/margins={"l":0,"t":0,"b":0,"r":0} -> 1 diff --git a/phase0_findings.md b/phase0_findings.md index 8529ea9..baaf8c4 100644 --- a/phase0_findings.md +++ b/phase0_findings.md @@ -146,7 +146,7 @@ Stock Firefox 150.0.1 + `media.ffmpeg.vaapi.enabled=true` + `LIBVA_DRIVER_NAME=v **Result**: Firefox's RDD process dlopens libva.so.2 + libva-drm.so.2 + libva-x11.so.2 for capability probe then immediately closes them; never reaches `vaInitialize`. Gfx-environment platform-fitness check rejects VAAPI under Xvfb's software-framebuffer-with-no-DRI rig. Not a libva-side fault. Re-test in live session needed. -### Live Plasma Wayland session run — INVERTS PRIOR PHASE 0 VERDICT +### Live Plasma Wayland session run — and follow-up kernel-side disambiguation Same Firefox profile + LIBVA env, executed inside the operator's active Plasma 6 Wayland session (XDG_SESSION_TYPE=wayland, XDG_RUNTIME_DIR=/run/user/1001). Full write-up: [`phase0_evidence/2026-05-04-firefox-live/findings.md`](phase0_evidence/2026-05-04-firefox-live/findings.md). @@ -169,14 +169,36 @@ Phase 0 deliverable status corrections: - **#3** (Firefox configuration end-to-end) — ✓ engagement confirmed in live Plasma session; pixel-content failure mode identical to mpv. - **#4** (Phase 0 baseline anchor) — ✗ **AMENDED**: captured trace describes Step 1's userspace behaviour, not the kernel-side spec Phase 6 must reproduce. -**Phase 1 lock should be deferred** until: (a) the boolean-correctness criterion is sharpened to require pixel-content verification (sentinel-overwrite check, NV12 luma min/max sanity, etc.), and (b) Phase 0 includes a kernel-side observability layer (ftrace `events/v4l2/`, `dmesg` for silent decode errors) so we can characterize *why* hantro is silent. The Step 1 18-patch series engages libva but doesn't make hantro decode — Phase 6 has substantive work. +### Kernel-side re-baseline (2026-05-04) — corrects the prior verdict AGAIN -Likely failure-mode candidates (priority order, from patch comments): -1. `reference_ts` not propagated (per patch-0017 commit body: "hantro doesn't read pic_num, uses reference_ts") -2. DECODE_PARAMS slice_header bit_size fields all zero (patch 0008's open question, never resolved) -3. POC sentinel still leaking past patch-0015's strip (DEBUG dump runs *before* the strip; need post-strip verification via VIDIOC_G_EXT_CTRLS) -4. level_idc over-allocation interaction (patch 0013 → 0018 transition) -5. `V4L2_EVENT_SOURCE_CHANGE` not handled (open Q #5) +ftrace v4l2/vb2/dma_fence + dmesg + dynamic_debug enabled while running mpv `--hwdec=vaapi-copy --frames=2`. Full write-up: [`phase0_evidence/2026-05-04-kernel-trace/findings.md`](phase0_evidence/2026-05-04-kernel-trace/findings.md). + +| Layer | Result | +|---|---| +| ftrace `vb2_buf_done` for CAPTURE_MPLANE | **`bytesused=3655712`** (full NV12 + hantro tile padding) reported every frame. **Kernel signals successful full-buffer write.** | +| dmesg | Completely silent. No hantro/vpu/decode/fail/error/reject/einval/warn. | +| Real-VO disambiguator (operator inspection in live session) | `--hwdec=vaapi-copy --vo=gpu`: **solid GREEN frame**. `--hwdec=vaapi --vo=gpu`: **solid BLUE frame**. NV12-with-Y=0,UV=0 BT.709-converted = green; same buffer via DMA-BUF GL import with different colorspace = blue. **Neither shows the sentinel mid-beige pattern; neither shows real bunny pixels.** | + +**Corrected verdict**: hantro accepts the request, returns success, **and writes ALL ZEROS to the CAPTURE buffer**. The patch-0011 sentinel test we relied on is misleading — it has a **cache-coherency bug**. Patch 0011 writes `0xab` via cached `surface_object->destination_map[0]` mmap, but neither `0010-DEBUG-hex-dump` nor any other read path in libva-v4l2-request invalidates the cache after DQBUF. So the readback always shows the stale sentinel, hiding the fact that the kernel DMA-overwrote it with zeros. vaapi-copy and Mesa DMA-BUF GL import correctly invalidate cache and see the real (zero) contents. + +**Bug surface narrows substantially.** The path is: +- libva engagement: ✓ +- Contract trace: ✓ no EINVAL, all ioctls succeed +- Hantro request acceptance: ✓ kernel reports success +- **Hantro produces meaningful pixel output: ✗ writes ALL ZEROS** — almost certainly the bitstream parser silently rejects something (per patch-0011's own commit-message hypothesis: "the apparent 'no picture' output is the kernel-side decode actually producing zeros, e.g. parser rejected the bitstream") + +This is consistent with a control-submission bug (something in SPS/PPS/DECODE_PARAMS is off), not a fundamental "we can't drive hantro" problem. Phase 6 work direction sharpens accordingly. + +### Phase 6 priority list (revised after kernel-side baseline) + +1. **Fix the patch-0011 sentinel test** (or replace it). Add `msync(MS_SYNC|MS_INVALIDATE)` or DMA-BUF cache sync before the readback. Without this, future debugging is unreliable in exactly the same way. +2. **VIDIOC_G_EXT_CTRLS readback** of the request fd before QUEUE — confirms our writes actually stick at the V4L2 layer (e.g. POC sentinel actually stripped to 0 by patch-0015, level_idc actually set, etc.). +3. **Diff our per-frame control set against FFmpeg's `v4l2_request_h264.c`** (proven working on hantro, downstream branch `code.ffmpeg.org/Kwiboo/FFmpeg.git v4l2-request-n8.1`). Identify any field FFmpeg sets that we don't. +4. **Verify SPS submission completeness**: VAAPI's `VAPictureParameterBufferH264` doesn't carry the full SPS — we may need to derive `profile_idc` / `seq_parameter_set_id` / `log2_max_frame_num_minus4` / `pic_order_cnt_type` / `log2_max_pic_order_cnt_lsb_minus4` / `max_num_ref_frames` from VAAPI fields or by parsing the slice header. +5. **DECODE_PARAMS slice_header bit_size fields** (patch 0008's never-resolved question): if hantro requires them for parse, our zeros could be the silent-reject trigger. +6. **dyndbg on hantro module**: reload with `dyndbg="file drivers/media/platform/verisilicon/* +pmflt"` to surface compiled-in `dev_dbg` calls for the next probe. + +Phase 1 boolean-correctness criterion now must include pixel-content verification — but the verification can't rely on patch 0011 in its current form. Either fix patch 0011's cache sync, or use a different check: e.g. mpv `--vo=image-sequence` and inspect the dumped frame, or a small C reproducer that maps the buffer with proper cache flags and computes a luma histogram. ## Source-read references (carry-over from STUDY.md)