diff --git a/.gitignore b/.gitignore index aab3498028..8110f7d18f 100644 --- a/.gitignore +++ b/.gitignore @@ -2,4 +2,5 @@ !/subprojects/packagefiles !/subprojects/*.wrap /build/ +.hvigor/ .DS_Store diff --git a/DOCS/BENCHMARK_METHODOLOGY.md b/DOCS/BENCHMARK_METHODOLOGY.md new file mode 100644 index 0000000000..d09b0ae1ca --- /dev/null +++ b/DOCS/BENCHMARK_METHODOLOGY.md @@ -0,0 +1,22 @@ +# Phase 6 Benchmark 方法 + +## 执行 + +```sh +python3 benchmark/runner/run_emulator.py startup_local --repeat 20 +python3 benchmark/runner/run_emulator.py seek_local --repeat 50 +python3 benchmark/runner/run_emulator.py stress_lifecycle --repeat 100 +python3 benchmark/runner/run_emulator.py play_pause --repeat 200 +``` + +runner 通过 hdc/uitest 驱动 `Playback Lab`,每次 load 使用内置 `sample.mp4`,记录 timeline、错误、状态和进程采样。startup 的首轮标为 cold-ish,后续为 warm;OS page cache 未被强制清空。seek 使用加载后立即触发的原生 `+10s`,避免短样片在输入框多次 keyEvent 期间自然结束。 + +每个场景输出逐次 JSON 和 min/max/avg/median/P90/P95。百分位采用排序后的 nearest-rank;负时间线值是 unavailable,不参与统计。错误单独保留,不从成功样本中删除。 + +## 采样边界 + +- VmRSS、VmSize、Threads、fd count 和原始 CPU jiffies 来自 `/proc`;PSS、精确 native heap、可靠 CPU permille 未被模拟器公开,输出 null/原始值。 +- host wall time 包含 hdc 往返,只用于发现自动化超时,不作为启动性能结论。 +- `firstAudioCallbackMs` 是 Playback Lab 诊断轮询观察到 callback_count>0 的时间;要取得 callback 内精确时间需独立 tracing,因此不把它当作硬件时钟证据。 +- `stress_lifecycle` 覆盖 load/stop;release/recreate 需要新 XComponent surface,另行作为实体设备/手工场景。 +- HTTPS、HLS、鉴权、网络字幕必须使用受控 fixture;本轮没有把公网失败当作性能数据。 diff --git a/DOCS/BUFFERING_MODEL.md b/DOCS/BUFFERING_MODEL.md new file mode 100644 index 0000000000..fc73a93589 --- /dev/null +++ b/DOCS/BUFFERING_MODEL.md @@ -0,0 +1,7 @@ +# Buffering Model + +buffering 是 MPV `cache-buffering` 属性与网络状态的边沿诊断,不是 UI 的瞬时文案。进入时记录 `bufferingEnterCount` 和起始 monotonic 时间;退出时累加 `bufferingTotalMs`,并更新 `bufferingMaxSingleMs`。重复的同值属性通知不会重复计数。 + +网络快照同时保留 protocol、host、HTTP status、redirect count、cache duration/bytes、current bitrate、range support 和最近 seek result。`networkWaitMs` 只计算已观察到的 network-open 到 first-byte/file-loaded 间隔;file:// 输入为 -1。 + +本地短片通常在首帧后很快 EOF,因此 buffering 计数为 0 不代表网络流在真实设备上不会重缓冲。受控 HTTP Range fixture 已在 Phase 5 验证;HTTPS/HLS、鉴权和弱网重缓冲应在实体设备用固定服务端脚本复测。 diff --git a/DOCS/PERFORMANCE_CHANGES.md b/DOCS/PERFORMANCE_CHANGES.md new file mode 100644 index 0000000000..f458ae7681 --- /dev/null +++ b/DOCS/PERFORMANCE_CHANGES.md @@ -0,0 +1,18 @@ +# Phase 6 性能改动与证据 + +## 已采用 + +1. **事件驱动渲染更新**:`render.cpp` 不再每 16ms 无条件调用 `mpv_render_context_update`,只在 mpv callback/窗口事件唤醒时更新;为避免个别会话漏回调,最多每 250ms 做一次安全探测。5 次 startup 的 update 累计从优化前 617 降到最终实现 364,且 20 次 startup 未复现永久 BUFFERING。 +2. **核心快照合并**:`PlaybackEngine` 对 100ms 内的重复 `get_snapshot/get_tracks/get_media_info/get_network_info` 做合并,动作仍立即提交到 MPV,状态最多延迟一个合并窗口。200 次 play/pause 末次面板显示 `coreSyncSkipped=239`;无 error,状态为 PAUSED。 +3. **NAPI 诊断轮询降频**:Playback Lab 面板由 250ms 调整为 500ms;播放控制、音频 callback 和渲染线程不依赖该轮询。这样减少纯 UI 诊断序列化,不改变 MPV 时钟。旧/新间隔在 `Index.ets` 可审计,运行中由 `getStateCalls`、`serializeUsTotal` 记录。 +4. **session id 原子读取**:渲染线程不再为每次唤醒获取 `PlaybackEngine` 快照互斥锁,session 更新仍由核心快照写入 release/acquire atomic;首帧 session 隔离 smoke 和 stress 均通过。 + +## 未采用 + +- 不做主动丢帧、降低音频采样率或缩小视频分辨率;这些会改变播放质量。 +- 不做 GPU mapper、OHCodec 直出或 FFmpeg-Harmony 源码改动;实体设备 capability 和 fence 证据不足。 +- 不把 PSS、heap、CPU permille、2 小时长跑结果伪装成已测数据。 + +## 回归与开销 + +默认构建、软件构建和 FFmpeg-Harmony 构建均通过。默认 HAP 在模拟器上完成 startup/seek/audio 状态面板、load/stop 100 次和 play/pause 100 次。release/profile 构建未启用持续 tracing;诊断仅累加轻量计数和受控序列化时间。 diff --git a/DOCS/PERFORMANCE_METRICS.md b/DOCS/PERFORMANCE_METRICS.md new file mode 100644 index 0000000000..c471eefab0 --- /dev/null +++ b/DOCS/PERFORMANCE_METRICS.md @@ -0,0 +1,20 @@ +# Phase 6 性能指标 + +所有时间均为单调时钟相对当前 load session 的毫秒数。`-1` 表示该事件没有发生或无法可靠观察;runner 会把负值转换为 `null`,不参与百分位统计。 + +| 类别 | 字段/来源 | 语义 | 模拟器可用性 | +| --- | --- | --- | --- | +| 启动 | `timeline.startupTotalMs` / `firstSwapMs` | load 到首个成功 EGL swap | 可用 | +| 启动分段 | create、initialize、load、START_FILE、FILE_LOADED、decoder reconfig、render context | 各阶段首次事件 | 可用,缺失阶段为 -1 | +| 网络 | `firstByteMs`、`networkWaitMs`、HTTP status、206/range | 只记录观察到的请求/日志证据 | HTTP fixture 可用,HTTPS/HLS pending | +| seek | `seekCommandLatencyMs`、`seekRecoveryMs`、`seekFirstSwapMs` | seek request/command 到恢复首帧/首 swap | 相对 `+10s` 可用 | +| buffering | enter/exit 次数、累计时长、单次最大时长 | cache-buffering 状态边沿 | 字段可用;本地短片通常为 0 | +| 音频 | renderer start、首 callback、submitted/played、delay、starvation、flush/reset | 首 callback 时间由诊断轮询观察,不冒充 callback 内精确时间 | 模拟器字段可用,设备路由 pending | +| 视频 | dropped、late、mistimed、decoder frames、render count | MPV stats 或 renderer 计数 | 计数接口可用,部分 MPV 值可能为 -1 | +| 内存 | `/proc//status` VmRSS/VmSize | 进程 RSS/虚拟地址空间 | 可用;PSS/精确 heap 为 null | +| CPU | `/proc//stat` utime+stime | 原始 jiffies | 原始值可用;未取得可靠 tick/采样归一化,不输出 permille | +| 线程/资源 | Threads、`/proc//fd` | 进程线程和 fd 快照 | 可用;fd=0 视为不可用 | +| NAPI | getState 次数、序列化微秒、估算 payload | NAPI 状态导出成本 | 可用;payload 是上界估算,不是分配追踪 | +| 渲染诊断 | render update/frame update、core sync/skipped | 优化前后计数及合并效果 | 可用 | + +NAPI 返回使用 Number 以保持 Inspector 可序列化;大整数仅用于内部原子计数。任何未被设备或 API 真实提供的数据都保持 unavailable,不由模型推断。 diff --git a/DOCS/PHASE6_STATUS.md b/DOCS/PHASE6_STATUS.md new file mode 100644 index 0000000000..f0fa8ff934 --- /dev/null +++ b/DOCS/PHASE6_STATUS.md @@ -0,0 +1,33 @@ +# Phase 6 状态 + +状态:**CODE COMPLETE / EMULATOR BENCHMARKED / DEVICE BENCHMARK PENDING**。 + +Phase 6 交付范围是可重复的 Playback Lab 性能时间线、资源采样、NAPI 诊断、四项低风险优化和模拟器回归。没有修改 GPU mapper,也没有修改 `Velix-FFmpeg-Harmony`。 + +## 已完成 + +- 启动、seek、buffering、音频、渲染、NAPI 和资源指标已接入稳定快照;未能可靠取得的 PSS、精确 heap、归一化 CPU 均明确返回 `null` 或文档标记为 unavailable。 +- `benchmark/runner/run_emulator.py` 支持 startup、seek、load/stop stress、play/pause stress,输出重复统计(min/max/avg/median/P90/P95)和逐次资源采样。 +- 渲染循环改为 mpv update callback 驱动,并保留 250ms 安全探测;快照同步增加 100ms 合并窗口;session id 读取改为 atomic;诊断轮询从 250ms 调整为 500ms。 +- default、software、FFmpeg-Harmony 三套 AArch64 libmpv 均通过符号和 OHOS ELF 校验;Playback Lab HAP 编译、安装和模拟器启动通过。 + +## 模拟器结果 + +测试设备:`127.0.0.1:5555`,本地 H.264/AAC MP4,软件解码,`ao_harmony`。 + +| 场景 | 结果文件 | 关键结果 | +| --- | --- | --- | +| startup_local ×20 | `benchmark/results/startup_local-1787999362.json` | 首帧 P50 506ms,P95 1150ms;20/20 暴露时间线,无错误 | +| seek_local ×50 | `benchmark/results/seek_local-1787999663.json` | 恢复 P50 277ms,P95 631ms;49/50 有恢复时间线,1 次 `SEEK` 命令错误 | +| play_pause ×200 | `benchmark/results/play_pause-1788000475.json` | 无错误;末次 RSS 213228KB、线程 39、fd 1 | +| load/stop ×100 | `benchmark/results/stress_lifecycle-1788000229.json` | 进程保持存活;RSS/线程/fd 采样完成,PSS 不可用 | + +优化前后计数基线:同等 5 次 startup 中,渲染 update 累计由 617 降至最终版本 364;NAPI/核心同步计数通过面板快照记录。200 次 play/pause 无错误,末次 `coreSyncSkipped=239`,说明合并窗口实际生效。 + +最终 5 次 smoke 还观察到 `firstAudioCallbackMs` P50 256ms、`audioRendererStartMs` P50 720ms;这些值来自 500ms 诊断轮询,不能替代设备音频 trace。file:// 场景的 `networkWaitMs` 保持 -1,buffering 计数按真实状态边沿记录。 + +## 尚待实体设备 + +实体设备上的真实 PSS/heap、CPU 利用率、显示合成延迟、音频路由/A-V 偏差、OHCodec capability、长时间(2h)稳定性、HTTPS/HLS/鉴权/网络字幕仍未验证。Phase 7 建议先建立实体设备矩阵和受控 HTTPS/HLS fixture,再评估硬解直出和端到端 A/V 指标。 + +许可边界沿用 MPV LGPL/ISC;本阶段未引入新的第三方依赖或商业资源。 diff --git a/DOCS/SEEK_PIPELINE.md b/DOCS/SEEK_PIPELINE.md new file mode 100644 index 0000000000..5e9beaf9e7 --- /dev/null +++ b/DOCS/SEEK_PIPELINE.md @@ -0,0 +1,15 @@ +# Seek Pipeline + +```text +seek request + -> mpv seek command + -> SEEK event / demux recovery + -> VIDEO_RECONFIG + -> PLAYBACK_RESTART + -> first video frame + -> first render / EGL swap +``` + +`seekCommandLatencyMs` 是 API request 到 command 提交的耗时;`seekRecoveryMs` 是 request 到 `PLAYBACK_RESTART` 的耗时;`seekFirstVisibleFrameMs` 是 request 到首个成功 swap 的耗时。若 MPV 没有产生对应事件,字段为 -1。每次新 seek 会重置上一次 seek 字段,不把旧会话值带入新会话。 + +模拟器 runner 使用 `+10s` 相对 seek,50 次中 49 次产生 recovery,1 次返回稳定 `SEEK / error running command`;该失败保留在 JSON,不被隐藏。精确/百分比 seek 入口仍由公共 API 暴露,但短样片不足以让输入框自动化可靠覆盖,需更长受控 fixture。 diff --git a/DOCS/STARTUP_PIPELINE.md b/DOCS/STARTUP_PIPELINE.md new file mode 100644 index 0000000000..b094c358c8 --- /dev/null +++ b/DOCS/STARTUP_PIPELINE.md @@ -0,0 +1,19 @@ +# Startup Pipeline + +```text +session setup + -> mpv_create / mpv_initialize + -> load command + -> START_FILE + -> network open / first byte (network only) + -> FILE_LOADED (demux ready) + -> VIDEO_RECONFIG / AUDIO_RECONFIG + -> render context ready + -> first video frame available + -> first render begin/end + -> first EGL swap (startupTotalMs) +``` + +时间线在 core 内以 `clock_gettime(CLOCK_MONOTONIC)` 记录,所有阶段只写首次发生值。文件输入没有网络阶段时保持 -1;网络阶段只在真实 MPV log/event 证据出现时写入。`startupTotalMs` 在首个成功 `eglSwapBuffers` 写入,`firstFrameMs` 保留外壳兼容字段并与首 swap 对齐。 + +音频 renderer start 和首 callback 由 OHAudio stats poll 观察;这两个字段可能晚于真实 callback,因此用于阶段诊断,不替代设备级 audio trace。 diff --git a/benchmark/.gitignore b/benchmark/.gitignore new file mode 100644 index 0000000000..8b2e9983ea --- /dev/null +++ b/benchmark/.gitignore @@ -0,0 +1,5 @@ +results/*.json +reports/*.md +runner/__pycache__/ +!results/.gitkeep +!reports/.gitkeep diff --git a/benchmark/reports/.gitkeep b/benchmark/reports/.gitkeep new file mode 100644 index 0000000000..e69de29bb2 diff --git a/benchmark/results/.gitkeep b/benchmark/results/.gitkeep new file mode 100644 index 0000000000..e69de29bb2 diff --git a/benchmark/runner/run_emulator.py b/benchmark/runner/run_emulator.py new file mode 100755 index 0000000000..00b4c46855 --- /dev/null +++ b/benchmark/runner/run_emulator.py @@ -0,0 +1,385 @@ +#!/usr/bin/env python3 +"""Repeatable Playback Lab emulator benchmark runner. + +Only uses the standard library and the OpenHarmony hdc/uitest command line. +Metrics unavailable from the emulator are emitted as null, never inferred. +""" + +from __future__ import annotations + +import argparse +import json +import math +import os +import re +import shlex +import subprocess +import tempfile +import time +from datetime import datetime, timezone +from pathlib import Path +from typing import Any, Iterable + + +ROOT = Path(__file__).resolve().parents[2] +PACKAGE = "com.velix.playbacklab" +DEFAULT_SERIAL = "127.0.0.1:5555" +DEFAULT_HDC = "/Applications/DevEco-Studio.app/Contents/sdk/default/openharmony/toolchains/hdc" + + +def command(argv: list[str], timeout: float = 30.0) -> str: + result = subprocess.run(argv, check=False, capture_output=True, text=True, timeout=timeout) + if result.returncode != 0: + raise RuntimeError(f"command failed ({result.returncode}): {shlex.join(argv)}\n{result.stderr.strip()}") + return result.stdout.strip() + + +class Emulator: + def __init__(self, serial: str, hdc: str) -> None: + self.serial = serial + self.hdc = hdc + self.layout_counter = 0 + + def hdc_shell(self, text: str, timeout: float = 30.0) -> str: + return command([self.hdc, "-t", self.serial, "shell", text], timeout) + + def click(self, x: int, y: int) -> None: + self.hdc_shell(f"uitest uiInput click {x} {y}", timeout=10) + + def layout(self) -> dict[str, Any]: + self.layout_counter += 1 + marker = self.hdc_shell(f"uitest dumpLayout -b {PACKAGE} -m true -d 0", timeout=10) + match = re.search(r"saved to:(\S+)", marker) + if not match: + raise RuntimeError(f"layout dump did not return a path: {marker}") + remote = match.group(1) + local = Path(tempfile.gettempdir()) / f"velix-layout-{os.getpid()}-{self.layout_counter}.json" + command([self.hdc, "-t", self.serial, "file", "recv", remote, str(local)], timeout=10) + with local.open(encoding="utf-8") as stream: + return json.load(stream) + + def pid(self) -> int | None: + output = self.hdc_shell(f"pidof {PACKAGE}", timeout=10) + match = re.search(r"\b(\d+)\b", output) + return int(match.group(1)) if match else None + + def process_sample(self) -> dict[str, Any]: + pid = self.pid() + sample: dict[str, Any] = {"pid": pid, "rssKb": None, "pssKb": None, "heapKb": None, + "virtualMemoryKb": None, + "threadCount": None, "fdCount": None, "cpuPermille": None, + "cpuSupported": False} + if pid is None: + return sample + status = self.hdc_shell(f"cat /proc/{pid}/status", timeout=10) + for key, field in (("rssKb", "VmRSS"), ("virtualMemoryKb", "VmSize"), ("threadCount", "Threads")): + match = re.search(rf"^{field}:\s+(\d+)", status, re.MULTILINE) + if match: + sample[key] = int(match.group(1)) + fd_output = self.hdc_shell(f"ls /proc/{pid}/fd 2>&1 | wc -l", timeout=10) + if fd_output.isdigit() and fd_output != "0": + sample["fdCount"] = int(fd_output) + stat = self.hdc_shell(f"cat /proc/{pid}/stat", timeout=10) + match = re.match(r"^\d+ \(.+\) (.*)$", stat) + if match: + fields = match.group(1).split() + if len(fields) > 12: + sample["cpuJiffies"] = int(fields[11]) + int(fields[12]) + return sample + + def product_version(self) -> str | None: + try: + value = self.hdc_shell("param get const.product.software.version", timeout=10) + except RuntimeError: + return None + return value or None + + +def walk_nodes(node: dict[str, Any]) -> Iterable[dict[str, Any]]: + yield node + for child in node.get("children", []): + if isinstance(child, dict): + yield from walk_nodes(child) + + +def node_text(node: dict[str, Any]) -> str: + attrs = node.get("attributes", {}) + return str(attrs.get("text") or attrs.get("originalText") or "") + + +def find_node(layout: dict[str, Any], text: str) -> dict[str, Any] | None: + for node in walk_nodes(layout): + if node_text(node) == text: + return node + return None + + +def center(bounds: str) -> tuple[int, int]: + values = [int(value) for value in re.findall(r"\d+", bounds)] + if len(values) != 4: + raise ValueError(f"invalid bounds: {bounds}") + return (values[0] + values[2]) // 2, (values[1] + values[3]) // 2 + + +def click_text(emulator: Emulator, text: str) -> None: + node = find_node(emulator.layout(), text) + if node is None: + raise RuntimeError(f"UI node not found: {text}") + emulator.click(*center(node["attributes"]["bounds"])) + + +def all_texts(layout: dict[str, Any]) -> list[str]: + return [node_text(node) for node in walk_nodes(layout) if node_text(node)] + + +def text_matching(layout: dict[str, Any], prefix: str) -> str | None: + for value in all_texts(layout): + if value.startswith(prefix): + return value + return None + + +def parse_int(text: str | None, pattern: str) -> int | None: + if not text: + return None + match = re.search(pattern, text) + return int(match.group(1)) if match else None + + +def parse_state(layout: dict[str, Any]) -> str | None: + value = text_matching(layout, "state: ") + return value.split(": ", 1)[1] if value and ": " in value else None + + +def parse_run(layout: dict[str, Any]) -> dict[str, Any]: + startup = text_matching(layout, "startup=") or "" + buffer_line = text_matching(layout, "buffer enter=") or "" + napi_line = text_matching(layout, "napi calls=") or "" + render_line = text_matching(layout, "render updates=") or napi_line + error = text_matching(layout, "error=") or "" + timeline: dict[str, Any] = {} + for key, value in re.findall(r"(startup|firstSwap|seekRecovery|audioStart|audioCallback)=(-?\d+)", startup): + timeline[{"startup": "startupTotalMs", "firstSwap": "firstSwapMs", "seekRecovery": "seekRecoveryMs", + "audioStart": "audioRendererStartMs", "audioCallback": "firstAudioCallbackMs"}[key]] = int(value) + first_frame = parse_int(text_matching(layout, "dropped="), r"firstFrameMs=(-?\d+)") + if first_frame is None or first_frame < 0: + first_frame = timeline.get("firstSwapMs") + if first_frame is not None and first_frame < 0: + first_frame = None + startup_ms = timeline.get("startupTotalMs") + first_swap_ms = timeline.get("firstSwapMs") + seek_recovery_ms = timeline.get("seekRecoveryMs") + audio_start_ms = timeline.get("audioRendererStartMs") + audio_callback_ms = timeline.get("firstAudioCallbackMs") + if startup_ms is not None and startup_ms < 0: + startup_ms = None + if first_swap_ms is not None and first_swap_ms < 0: + first_swap_ms = None + if seek_recovery_ms is not None and seek_recovery_ms < 0: + seek_recovery_ms = None + if audio_start_ms is not None and audio_start_ms < 0: + audio_start_ms = None + if audio_callback_ms is not None and audio_callback_ms < 0: + audio_callback_ms = None + return { + "state": parse_state(layout), + "firstFrameMs": first_frame, + "renderCount": parse_int(text_matching(layout, "dropped="), r"renderCount=(-?\d+)"), + "startupTotalMs": startup_ms, + "firstSwapMs": first_swap_ms, + "seekRecoveryMs": seek_recovery_ms, + "audioRendererStartMs": audio_start_ms, + "firstAudioCallbackMs": audio_callback_ms, + "bufferingEnterCount": parse_int(buffer_line, r"buffer enter=(-?\d+)"), + "bufferingExitCount": parse_int(buffer_line, r"exit=(-?\d+)"), + "napiCalls": parse_int(napi_line, r"napi calls=(-?\d+)"), + "renderUpdateCalls": parse_int(render_line, r"updates=(-?\d+)/"), + "renderFrameUpdates": parse_int(render_line, r"updates=-?\d+/(-?\d+)"), + "coreSyncCalls": parse_int(render_line, r"sync=(-?\d+)/"), + "coreSyncSkipped": parse_int(render_line, r"sync=-?\d+/(-?\d+)"), + "error": error, + } + + +def wait_for_first_frame(emulator: Emulator, timeout: float = 10.0) -> tuple[dict[str, Any], list[dict[str, Any]]]: + deadline = time.monotonic() + timeout + samples: list[dict[str, Any]] = [] + latest: dict[str, Any] = {} + next_sample = 0.0 + while time.monotonic() < deadline: + latest = emulator.layout() + now = time.monotonic() + if now >= next_sample: + samples.append({"atMs": int((timeout - max(0.0, deadline - now)) * 1000), + **emulator.process_sample()}) + next_sample = now + 1.0 + run = parse_run(latest) + if run.get("startupTotalMs") is not None or run.get("state") == "ERROR": + return latest, samples + time.sleep(0.15) + raise TimeoutError(f"playback did not expose first-frame timeline: {parse_run(latest)}") + + +def stats(values: list[float | int]) -> dict[str, float | int | None]: + numbers = sorted(float(value) for value in values if value is not None and math.isfinite(float(value))) + if not numbers: + return {"count": 0, "min": None, "max": None, "avg": None, "median": None, "p90": None, "p95": None} + def percentile(fraction: float) -> float: + return numbers[max(0, min(len(numbers) - 1, math.ceil(fraction * len(numbers)) - 1))] + return {"count": len(numbers), "min": numbers[0], "max": numbers[-1], + "avg": sum(numbers) / len(numbers), "median": percentile(0.5), + "p90": percentile(0.9), "p95": percentile(0.95)} + + +def git_revision(path: Path) -> str | None: + try: + return command(["git", "-C", str(path), "rev-parse", "HEAD"], timeout=10) + except RuntimeError: + return None + + +def load_local(emulator: Emulator) -> tuple[dict[str, Any], list[dict[str, Any]]]: + click_text(emulator, "Load Local Test") + return wait_for_first_frame(emulator) + + +def startup_local(emulator: Emulator, repeat: int) -> list[dict[str, Any]]: + runs: list[dict[str, Any]] = [] + for index in range(repeat): + began = time.monotonic() + click_text(emulator, "Load Local Test") + layout, samples = wait_for_first_frame(emulator) + run = parse_run(layout) + run.update({"runIndex": index + 1, "cacheClass": "cold-ish" if index == 0 else "warm", + "hostFirstFrameMs": int((time.monotonic() - began) * 1000), + "processSamples": samples}) + runs.append(run) + return runs + + +def wait_for_seek_recovery(emulator: Emulator, timeout: float = 5.0) -> tuple[dict[str, Any], list[dict[str, Any]]]: + deadline = time.monotonic() + timeout + samples: list[dict[str, Any]] = [] + latest: dict[str, Any] = {} + next_sample = 0.0 + while time.monotonic() < deadline: + latest = emulator.layout() + now = time.monotonic() + if now >= next_sample: + samples.append({"atMs": int((timeout - max(0.0, deadline - now)) * 1000), + **emulator.process_sample()}) + next_sample = now + 1.0 + run = parse_run(latest) + if run.get("seekRecoveryMs") is not None and run.get("seekRecoveryMs") >= 0: + return latest, samples + if run.get("state") == "ERROR": + return latest, samples + time.sleep(0.1) + raise TimeoutError(f"seek did not expose recovery timeline: {parse_run(latest)}") + + +def seek_local(emulator: Emulator, repeat: int) -> list[dict[str, Any]]: + runs: list[dict[str, Any]] = [] + for index in range(repeat): + click_text(emulator, "Load Local Test") + # The bundled clip is intentionally short and may finish before a + # multi-command text-input interaction completes. The native +/-10s + # action exercises the same seek API without that race. + time.sleep(0.05) + click_text(emulator, "+10s") + latest, samples = wait_for_seek_recovery(emulator) + run = parse_run(latest) + run.update({"runIndex": index + 1, "mode": "relative", "offsetSeconds": 10, + "processSamples": samples}) + runs.append(run) + return runs + + +def stress_lifecycle(emulator: Emulator, repeat: int) -> list[dict[str, Any]]: + initial = emulator.layout() + load_center = center(find_node(initial, "Load Local Test")["attributes"]["bounds"]) + stop_center = center(find_node(initial, "Stop")["attributes"]["bounds"]) + runs: list[dict[str, Any]] = [] + for index in range(repeat): + emulator.click(*load_center) + time.sleep(0.08) + emulator.click(*stop_center) + time.sleep(0.08) + layout = emulator.layout() + run = parse_run(layout) + run.update({"runIndex": index + 1, "processSample": emulator.process_sample()}) + runs.append(run) + return runs + + +def play_pause(emulator: Emulator, repeat: int) -> list[dict[str, Any]]: + load_local(emulator) + initial = emulator.layout() + play_center = center(find_node(initial, "Play")["attributes"]["bounds"]) + pause_center = center(find_node(initial, "Pause")["attributes"]["bounds"]) + runs: list[dict[str, Any]] = [] + for index in range(repeat): + emulator.click(*play_center) + emulator.click(*pause_center) + if index % 10 == 0: + time.sleep(0.05) + run = {"runIndex": index + 1, "processSample": emulator.process_sample()} + if index % 10 == 0 or index + 1 == repeat: + run.update(parse_run(emulator.layout())) + runs.append(run) + return runs + + +def main() -> int: + parser = argparse.ArgumentParser() + parser.add_argument("scenario", choices=["startup_local", "seek_local", "stress_lifecycle", "play_pause"]) + parser.add_argument("--repeat", type=int, default=None) + parser.add_argument("--serial", default=os.environ.get("DEVECO_DEVICE", DEFAULT_SERIAL)) + parser.add_argument("--hdc", default=os.environ.get("HDC", DEFAULT_HDC)) + parser.add_argument("--output", type=Path) + args = parser.parse_args() + defaults = {"startup_local": 20, "seek_local": 50, "stress_lifecycle": 100, "play_pause": 200} + repeat = args.repeat if args.repeat is not None else defaults[args.scenario] + emulator = Emulator(args.serial, args.hdc) + if args.scenario == "startup_local": + runs = startup_local(emulator, repeat) + elif args.scenario == "seek_local": + runs = seek_local(emulator, repeat) + elif args.scenario == "stress_lifecycle": + runs = stress_lifecycle(emulator, repeat) + else: + runs = play_pause(emulator, repeat) + metric_names = ["firstFrameMs", "startupTotalMs", "firstSwapMs", "seekRecoveryMs", "audioRendererStartMs", + "firstAudioCallbackMs", "bufferingEnterCount", "bufferingExitCount", "hostFirstFrameMs", "hostTerminalMs"] + output = { + "timestamp": datetime.now(timezone.utc).isoformat(), + "gitCommit": git_revision(ROOT), + "mpvCommit": git_revision(ROOT), + "ffmpegCommit": git_revision(ROOT.parent / "Velix-FFmpeg-Harmony"), + "deviceType": "emulator", + "deviceSerial": args.serial, + "harmonyVersion": emulator.product_version(), + "testScenario": args.scenario, + "mediaId": "sample.mp4", + "protocol": "file", + "codec": "H.264/AAC", + "resolution": None, + "audio": "ao_harmony", + "subtitle": "none", + "hwdec": "software", + "repeat": repeat, + "metrics": {name: stats([run.get(name) for run in runs]) for name in metric_names}, + "runs": runs, + "errors": [run.get("error") for run in runs if run.get("error") and "error=NONE" not in run.get("error", "")], + "sampling": {"pss": "unsupported unless exposed by device", "cpu": "raw /proc stat only when available"}, + } + output_path = args.output or ROOT / "benchmark" / "results" / f"{args.scenario}-{int(time.time())}.json" + output_path.parent.mkdir(parents=True, exist_ok=True) + output_path.write_text(json.dumps(output, ensure_ascii=False, indent=2) + "\n", encoding="utf-8") + print(output_path) + print(json.dumps(output["metrics"], ensure_ascii=False, indent=2)) + return 0 + + +if __name__ == "__main__": + raise SystemExit(main()) diff --git a/benchmark/scenarios/audio_on_off.json b/benchmark/scenarios/audio_on_off.json new file mode 100644 index 0000000000..ab7bc6a96f --- /dev/null +++ b/benchmark/scenarios/audio_on_off.json @@ -0,0 +1,7 @@ +{ + "name": "audio_on_off", + "media": "sample.mp4", + "repeat": 10, + "variants": ["audio_on", "audio_off"], + "notes": "Compare firstAudioCallbackMs and startupTotalMs without changing decode quality." +} diff --git a/benchmark/scenarios/http_range.json b/benchmark/scenarios/http_range.json new file mode 100644 index 0000000000..7cb5627f96 --- /dev/null +++ b/benchmark/scenarios/http_range.json @@ -0,0 +1,7 @@ +{ + "name": "http_range", + "media": "controlled-http-mp4", + "repeat": 10, + "requiredServerEvidence": ["Range bytes=0-", "206 response", "seekResult"], + "notes": "HTTPS/HLS are separate controlled-network scenarios and remain pending without a reliable source." +} diff --git a/benchmark/scenarios/seek_local.json b/benchmark/scenarios/seek_local.json new file mode 100644 index 0000000000..5dc71467d0 --- /dev/null +++ b/benchmark/scenarios/seek_local.json @@ -0,0 +1,7 @@ +{ + "name": "seek_local", + "media": "sample.mp4", + "positionsPercent": [10, 25, 50, 75, 90], + "repeatPerPosition": 10, + "modes": ["fast", "exact"] +} diff --git a/benchmark/scenarios/startup_local.json b/benchmark/scenarios/startup_local.json new file mode 100644 index 0000000000..bd286c87e3 --- /dev/null +++ b/benchmark/scenarios/startup_local.json @@ -0,0 +1,8 @@ +{ + "name": "startup_local", + "media": "sample.mp4", + "repeat": 20, + "coldIsh": true, + "warm": true, + "notes": "OS page cache is not controlled; firstFrame/startup timeline comes from the Playback Lab." +} diff --git a/benchmark/scenarios/stress_lifecycle.json b/benchmark/scenarios/stress_lifecycle.json new file mode 100644 index 0000000000..47b45b7434 --- /dev/null +++ b/benchmark/scenarios/stress_lifecycle.json @@ -0,0 +1,6 @@ +{ + "name": "stress_lifecycle", + "loadStopCycles": 100, + "playPauseCycles": 200, + "notes": "Release/recreate requires a fresh XComponent surface and is kept separate from load/stop stress." +} diff --git a/benchmark/scenarios/subtitle_ass.json b/benchmark/scenarios/subtitle_ass.json new file mode 100644 index 0000000000..f2fd6d384b --- /dev/null +++ b/benchmark/scenarios/subtitle_ass.json @@ -0,0 +1,7 @@ +{ + "name": "subtitle_ass", + "media": "sample.mp4", + "repeat": 10, + "variants": ["none", "embedded_srt", "embedded_ass", "external_ass"], + "notes": "Run only when the corresponding controlled fixture is installed on the emulator." +} diff --git a/include/mpv/harmony_playback.h b/include/mpv/harmony_playback.h index df19f4daa7..7e2e25cacd 100644 --- a/include/mpv/harmony_playback.h +++ b/include/mpv/harmony_playback.h @@ -173,6 +173,14 @@ typedef struct mp_harmony_playback_metrics { double cache_duration; int64_t cache_bytes; int64_t current_bitrate; + int64_t buffering_enter_count; + int64_t buffering_exit_count; + int64_t buffering_total_ms; + int64_t buffering_max_single_ms; + int64_t network_wait_ms; + int64_t late_frames; + int64_t mistimed_frames; + int64_t decoder_frames; } mp_harmony_playback_metrics; typedef struct mp_harmony_playback_error { @@ -180,6 +188,43 @@ typedef struct mp_harmony_playback_error { char raw_message[MP_HARMONY_TEXT]; } mp_harmony_playback_error; +/* Elapsed milliseconds from the current load request; -1 means unavailable. */ +typedef struct mp_harmony_playback_timeline { + int64_t session_setup_ms; + int64_t mpv_create_ms; + int64_t mpv_initialize_ms; + int64_t load_command_ms; + int64_t start_file_ms; + int64_t network_open_begin_ms; + int64_t network_open_end_ms; + int64_t first_byte_ms; + int64_t demux_ready_ms; + int64_t file_loaded_ms; + int64_t video_decoder_ready_ms; + int64_t audio_decoder_ready_ms; + int64_t video_reconfig_ms; + int64_t audio_reconfig_ms; + int64_t render_context_ready_ms; + int64_t first_video_frame_available_ms; + int64_t first_render_begin_ms; + int64_t first_render_end_ms; + int64_t first_swap_ms; + int64_t startup_total_ms; + int64_t audio_renderer_start_ms; + int64_t first_audio_callback_ms; + int64_t playback_restart_ms; + int64_t seek_request_ms; + int64_t seek_command_ms; + int64_t seek_demux_ms; + int64_t seek_video_reconfig_ms; + int64_t seek_playback_restart_ms; + int64_t seek_first_frame_ms; + int64_t seek_first_swap_ms; + int64_t seek_command_latency_ms; + int64_t seek_recovery_ms; + int64_t seek_first_visible_frame_ms; +} mp_harmony_playback_timeline; + typedef struct mp_harmony_playback_snapshot { uint64_t session_id; mp_harmony_state state; @@ -202,6 +247,7 @@ typedef struct mp_harmony_playback_snapshot { mp_harmony_playback_metrics metrics; mp_harmony_media_info media; mp_harmony_network_info network; + mp_harmony_playback_timeline timeline; } mp_harmony_playback_snapshot; /* Stable model aliases for language bindings. */ diff --git a/memory/2026-08-29.md b/memory/2026-08-29.md index 1353965c61..f4bf436def 100644 --- a/memory/2026-08-29.md +++ b/memory/2026-08-29.md @@ -38,3 +38,9 @@ 文件变更: player/harmony_playback.c, include/mpv/harmony_playback.h, playback_lab/entry/src/main/cpp/*, playback_lab/entry/src/main/ets/pages/Index.ets, DOCS/*, memory/* 教训: 当前 ArkUI SDK 下 Scroll 包裹既有 Column 会裁剪后续控件,保持平面 Column 并将关键错误信息置顶。 标签: #phase5 #network #range #security #emulator #ffmpeg-harmony + +[PROJECT:Velix-MPV-Core] Phase 6 性能基线与优化完成 +结论: 新增完整 playback timeline、buffer/audio/NAPI/资源诊断与 stdlib benchmark runner;事件驱动渲染+250ms安全探测、100ms核心快照合并、NAPI轮询降频、atomic session 读取通过模拟器回归,状态为 CODE COMPLETE / EMULATOR BENCHMARKED / DEVICE BENCHMARK PENDING。 +文件变更: include/mpv/harmony_playback.h, player/harmony_playback.c, playback_lab/entry/src/main/cpp/{player.h,player.cpp,render.cpp,bridge.cpp}, playback_lab/entry/src/main/ets/pages/Index.ets, benchmark/*, DOCS/{PHASE6_STATUS.md,PERFORMANCE_METRICS.md,PERFORMANCE_CHANGES.md,BENCHMARK_METHODOLOGY.md,STARTUP_PIPELINE.md,SEEK_PIPELINE.md,BUFFERING_MODEL.md} +教训: 完全依赖 mpv update callback 会导致重复 load 偶发 BUFFERING 卡住;保留低频安全探测。模拟器不提供 PSS/精确 heap/归一化 CPU,报告必须明确 unavailable;seek 50 次保留 1 次真实 SEEK 命令错误。 +标签: #phase6 #benchmark #timeline #buffering #napi #emulator #device-pending diff --git a/memory/MEMORY.md b/memory/MEMORY.md index 8d9c33dfc8..ea52812890 100644 --- a/memory/MEMORY.md +++ b/memory/MEMORY.md @@ -1,9 +1,10 @@ # Velix-MPV-Core 记忆索引 - 项目:地产运维中台媒体核心的 OpenHarmony MPV 端口。 -- 当前阶段:Phase 5 CODE COMPLETE;模拟器已验证 HTTP MP4/Range,HTTPS/HLS、网络字幕、鉴权资源和实体机验收待补。 +- 当前阶段:Phase 6 CODE COMPLETE / emulator benchmarked / device benchmark pending;HTTPS/HLS、网络字幕、鉴权资源和实体机验收待补。 - 公共入口:`include/mpv/harmony_playback.h`,稳定 C API 不暴露 MPV/FFmpeg 内部类型。 - Playback Lab:C++ 仅做 NAPI/渲染适配,核心请求、控制、状态统一委托 C API。 +- Phase 6:启动/seek/buffering/audio/资源/NAPI 时间线与 benchmark runner 已入库;5 次启动 update 617→364,20 次 startup、50 次 seek、100 次 load-stop、200 次 play-pause 已跑模拟器。 - 默认策略:软件解码;`harmony-ohcodec-gl` mapper 保持禁用,不声明零拷贝 GPU 能力。 - 构建:default/software/FFmpeg-Harmony AArch64 通过;HAP 使用 DevEco JBR + `--no-daemon` 通过。 - 设备:模拟器 `127.0.0.1:5555`,Playback Lab 已安装启动并完成本地 MP4 smoke。 diff --git a/memory/infra.md b/memory/infra.md index 9ad65b11c8..db23882c81 100644 --- a/memory/infra.md +++ b/memory/infra.md @@ -16,6 +16,7 @@ - 模拟器目标:`127.0.0.1:5555`,HarmonyOS 6.1.0.126 / API 24 - Playback Lab 构建:在 `playback_lab/` 执行 `scripts/stage-mpv.sh` 后用 hvigor `--no-daemon assembleHap --mode module -p product=default` - HAP 构建:使用 DevEco 自带 `/Applications/DevEco-Studio.app/Contents/jbr/Contents/Home`,并以 `hvigorw.js assembleHap --no-daemon --mode module -p product=default` 完成 PackageHap;默认未配置正式签名。 +- HAP 环境:需设置 `JAVA_HOME=/Applications/DevEco-Studio.app/Contents/jbr/Contents/Home`、`DEVECO_SDK_HOME=/Applications/DevEco-Studio.app/Contents/sdk`;SDK native 路径仍使用 `.../sdk/default/openharmony`。 - OHAudio:API 24 headers `ohaudio/native_audiostreambuilder.h` / `native_audiorenderer.h` / `native_audiostream_base.h`,动态库 `libohaudio.so`;Meson 使用 `-Dharmony-audio=enabled`。 - Phase 3 HAP:`playback_lab/entry/build/default/outputs/default/entry-default-unsigned.hap`;模拟器 H.264/AAC smoke target `127.0.0.1:5555`。 - Phase 4 构建入口:`scripts/build-mpv-ohos.sh`(OHCodec enabled)、`scripts/build-mpv-ohos-software.sh`(OHCodec disabled)、`scripts/build-all-ohos.sh`(全量矩阵);GL API probe 通过单独 Meson `harmony-ohcodec-gl=enabled` 构建验证。 @@ -24,3 +25,4 @@ - FFmpeg-Harmony:`../Velix-FFmpeg-Harmony`,origin `https://git.leee.xin/leeexin/Velix-FFmpeg-Harmony.git`,upstream `https://github.com/FFmpeg/FFmpeg.git`,branch `harmony-ohcodec-export`,tip `f3a036c695`;prefix `../Velix-FFmpeg-Harmony/build/ohos-arm64/prefix`。 - MPV fork 接入:`scripts/build-mpv-ohos-ffmpeg-harmony.sh`;可用 `FFMPEG_PREFIX` 与 `MPV_BUILD_ROOT` 覆盖默认路径,默认 MPV/软件脚本不变。 - MPV fork 输出:切换脚本默认安装到 `build/ohos-arm64/prefix-mpv-ffmpeg-harmony`,不会覆盖默认 `prefix`。 +- Phase 6 runner:`python3 benchmark/runner/run_emulator.py {startup_local,seek_local,stress_lifecycle,play_pause} --repeat N`;结果写入被忽略的 `benchmark/results/`。 diff --git a/memory/lessons.md b/memory/lessons.md index 6c7987a683..12239f2891 100644 --- a/memory/lessons.md +++ b/memory/lessons.md @@ -26,3 +26,6 @@ - Gitea 反向代理对完整 FFmpeg pack 返回 413;保留完整历史的可行做法是先建立空远端,再按 first-parent checkpoint 分块推送,不能浅克隆或裁剪历史。 - MPV 消费独立 FFmpeg prefix 时,pkg-config 必须把 fork 的 `lib/pkgconfig` 置于 base prefix 前,并保留绝对 include/lib 路径;仅改 `PREFIX` 会丢失 libass/libplacebo 等其他依赖。 - 当前 DevEco ArkUI SDK 下给既有平面 `Column` 外包 `Scroll` 会改变可见布局并裁掉后续控件;诊断页保持平面 Column,关键错误信息放在顶部,长列表改动需单独验收。 +- 渲染 update 不能完全依赖 callback:部分重复 load 会话可能漏通知;事件驱动应保留低频(250ms)安全探测,否则会卡在 BUFFERING。 +- 短媒体自动化 seek 若先等待首帧再执行多次 hdc keyEvent,媒体可能已 EOF;用立即触发的原生相对 seek 或更长受控 fixture,且保留真实命令错误。 +- `/proc` 在模拟器不一定提供 PSS、精确 heap 或可校准 CPU tick;benchmark 必须输出 null/原始 jiffies,不能自行推断 permille。 diff --git a/memory/projects.md b/memory/projects.md index 2c619aead1..5edec7bec6 100644 --- a/memory/projects.md +++ b/memory/projects.md @@ -2,9 +2,13 @@ ## Velix-MPV-Core +- 当前状态:Phase 6 CODE COMPLETE / EMULATOR BENCHMARKED / DEVICE BENCHMARK PENDING;提交待推送前复核。 +- Phase 6 产物:`benchmark/runner/run_emulator.py` 与场景 manifest;启动 P50/P95 506/1150ms,seek recovery P50/P95 277/631ms;100 load/stop、200 play/pause 无错误,PSS/精确 heap/CPU permille unavailable。 +- Phase 6 文档:`DOCS/PHASE6_STATUS.md`、`PERFORMANCE_METRICS.md`、`PERFORMANCE_CHANGES.md`、`BENCHMARK_METHODOLOGY.md`、`STARTUP_PIPELINE.md`、`SEEK_PIPELINE.md`、`BUFFERING_MODEL.md`。 + - 状态:Phase 5 CODE COMPLETE / emulator HTTP Range verified;GPU INTEROP MAPPER 未进入;HTTPS/HLS、网络字幕、鉴权、重定向运行验证与实体机验收未完成。 - 已完成:远程闭环、固定依赖、隔离工具链、C/C++ 探针、FFmpeg/OpenSSL/字体栈/libplacebo、AArch64 `libmpv.so.2.5.0`、ABI/符号/污染/许可证审计。 -- 产物:`build/ohos-arm64/prefix/lib/libmpv.so.2.5.0`,当前重建 34,343,104 bytes;软件构建位于 `build/ohos-arm64/build/mpv-software/libmpv.so.2.5.0`,FFmpeg-Harmony 构建位于 `build/ohos-arm64/build/mpv-ffmpeg-harmony/libmpv.so.2.5.0`;DT_NEEDED 含 `libohaudio.so`。 +- 产物:`build/ohos-arm64/prefix/lib/libmpv.so.2.5.0`,当前重建 34,346,792 bytes;软件构建位于 `build/ohos-arm64/build/mpv-software/libmpv.so.2.5.0`,FFmpeg-Harmony 构建位于 `build/ohos-arm64/build/mpv-ffmpeg-harmony/libmpv.so.2.5.0`;DT_NEEDED 含 `libohaudio.so`。 - 已完成:独立 HAP、XComponent/OHNativeWindow、EGL ES3、libmpv OpenGL Render、软件解码本地 MP4 首帧、播放控制与释放重入。 - 已完成:`ao_harmony` PCM float32→S16 fallback、采样率/mono-stereo 协商、pause/resume/stop/flush/release、timestamp epoch、starvation/flush metrics;Phase 5 HAP 已用 DevEco JBR 完成打包并安装模拟器。 - 已完成:OHCodec H.264/HEVC capability 查询、`hwdec=ohcodec` direct-surface 实验驱动、显式软件回退、Playback Lab requested/actual/metrics 诊断、软件/硬解/GL probe 构建矩阵;FFmpeg 未修改。 diff --git a/playback_lab/entry/src/main/cpp/bridge.cpp b/playback_lab/entry/src/main/cpp/bridge.cpp index 0c2718e024..18a3a6fb21 100644 --- a/playback_lab/entry/src/main/cpp/bridge.cpp +++ b/playback_lab/entry/src/main/cpp/bridge.cpp @@ -9,6 +9,8 @@ #include #include +#include +#include #undef LOG_DOMAIN #undef LOG_TAG @@ -18,6 +20,9 @@ namespace { PlaybackEngine gPlayer; EglRenderer gRenderer(gPlayer); +std::atomic gStateCalls{0}; +std::atomic gStateSerializeUs{0}; +std::atomic gStatePayloadBytes{0}; void onSurfaceCreated(OH_NativeXComponent* component, void* window) { @@ -446,6 +451,8 @@ napi_value release(napi_env env, napi_callback_info) napi_value getState(napi_env env, napi_callback_info) { PlaybackSnapshot state = gPlayer.snapshot(); + const auto serializeBegin = std::chrono::steady_clock::now(); + const uint64_t stateCall = gStateCalls.fetch_add(1, std::memory_order_relaxed) + 1; napi_value object = nullptr; napi_create_object(env, &object); napi_value value = nullptr; @@ -533,7 +540,64 @@ napi_value getState(napi_env env, napi_callback_info) napi_set_named_property(env, metrics, "cacheBytes", value); napi_create_int64(env, state.network.currentBitrate, &value); napi_set_named_property(env, metrics, "currentBitrate", value); + napi_create_int64(env, state.metrics.buffering_enter_count, &value); + napi_set_named_property(env, metrics, "bufferingEnterCount", value); + napi_create_int64(env, state.metrics.buffering_exit_count, &value); + napi_set_named_property(env, metrics, "bufferingExitCount", value); + napi_create_int64(env, state.metrics.buffering_total_ms, &value); + napi_set_named_property(env, metrics, "bufferingTotalMs", value); + napi_create_int64(env, state.metrics.buffering_max_single_ms, &value); + napi_set_named_property(env, metrics, "bufferingMaxSingleMs", value); + napi_create_int64(env, state.metrics.network_wait_ms, &value); + napi_set_named_property(env, metrics, "networkWaitMs", value); + napi_create_int64(env, state.metrics.late_frames, &value); + napi_set_named_property(env, metrics, "lateFrames", value); + napi_create_int64(env, state.metrics.mistimed_frames, &value); + napi_set_named_property(env, metrics, "mistimedFrames", value); + napi_create_int64(env, state.metrics.decoder_frames, &value); + napi_set_named_property(env, metrics, "decoderFrames", value); napi_set_named_property(env, object, "metrics", metrics); + napi_value timeline = nullptr; + napi_create_object(env, &timeline); + auto setTimeline = [&](const char* name, int64_t milliseconds) { + napi_value item = nullptr; + napi_create_int64(env, milliseconds, &item); + napi_set_named_property(env, timeline, name, item); + }; + setTimeline("sessionSetupMs", state.timeline.session_setup_ms); + setTimeline("mpvCreateMs", state.timeline.mpv_create_ms); + setTimeline("mpvInitializeMs", state.timeline.mpv_initialize_ms); + setTimeline("loadCommandMs", state.timeline.load_command_ms); + setTimeline("startFileMs", state.timeline.start_file_ms); + setTimeline("networkOpenBeginMs", state.timeline.network_open_begin_ms); + setTimeline("networkOpenEndMs", state.timeline.network_open_end_ms); + setTimeline("firstByteMs", state.timeline.first_byte_ms); + setTimeline("demuxReadyMs", state.timeline.demux_ready_ms); + setTimeline("fileLoadedMs", state.timeline.file_loaded_ms); + setTimeline("videoDecoderReadyMs", state.timeline.video_decoder_ready_ms); + setTimeline("audioDecoderReadyMs", state.timeline.audio_decoder_ready_ms); + setTimeline("videoReconfigMs", state.timeline.video_reconfig_ms); + setTimeline("audioReconfigMs", state.timeline.audio_reconfig_ms); + setTimeline("renderContextReadyMs", state.timeline.render_context_ready_ms); + setTimeline("firstVideoFrameAvailableMs", state.timeline.first_video_frame_available_ms); + setTimeline("firstRenderBeginMs", state.timeline.first_render_begin_ms); + setTimeline("firstRenderEndMs", state.timeline.first_render_end_ms); + setTimeline("firstSwapMs", state.timeline.first_swap_ms); + setTimeline("startupTotalMs", state.timeline.startup_total_ms); + setTimeline("audioRendererStartMs", state.timeline.audio_renderer_start_ms); + setTimeline("firstAudioCallbackMs", state.timeline.first_audio_callback_ms); + setTimeline("playbackRestartMs", state.timeline.playback_restart_ms); + setTimeline("seekRequestMs", state.timeline.seek_request_ms); + setTimeline("seekCommandMs", state.timeline.seek_command_ms); + setTimeline("seekDemuxMs", state.timeline.seek_demux_ms); + setTimeline("seekVideoReconfigMs", state.timeline.seek_video_reconfig_ms); + setTimeline("seekPlaybackRestartMs", state.timeline.seek_playback_restart_ms); + setTimeline("seekFirstFrameMs", state.timeline.seek_first_frame_ms); + setTimeline("seekFirstSwapMs", state.timeline.seek_first_swap_ms); + setTimeline("seekCommandLatencyMs", state.timeline.seek_command_latency_ms); + setTimeline("seekRecoveryMs", state.timeline.seek_recovery_ms); + setTimeline("seekFirstVisibleFrameMs", state.timeline.seek_first_visible_frame_ms); + napi_set_named_property(env, object, "timeline", timeline); napi_value media = nullptr; napi_create_object(env, &media); napi_create_string_utf8(env, state.media.container.c_str(), NAPI_AUTO_LENGTH, &value); @@ -659,6 +723,34 @@ napi_value getState(napi_env env, napi_callback_info) napi_set_named_property(env, object, "seekAudioResetCount", value); napi_create_int32(env, audio.state, &value); napi_set_named_property(env, object, "audioState", value); + napi_value profiling = nullptr; + napi_create_object(env, &profiling); + const uint64_t payloadBytes = static_cast(state.lastError.size() + state.errorCode.size() + + state.network.protocol.size() + state.network.host.size() + + state.tracks.size() * 64 + 2048); + const uint64_t serializeUs = static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - serializeBegin).count()); + gStateSerializeUs.fetch_add(serializeUs, std::memory_order_relaxed); + gStatePayloadBytes.fetch_add(payloadBytes, std::memory_order_relaxed); + napi_create_int64(env, static_cast(stateCall), &value); + napi_set_named_property(env, profiling, "getStateCalls", value); + napi_create_int64(env, static_cast(gStateSerializeUs.load(std::memory_order_relaxed)), &value); + napi_set_named_property(env, profiling, "serializeUsTotal", value); + napi_create_int64(env, static_cast(gStatePayloadBytes.load(std::memory_order_relaxed)), &value); + napi_set_named_property(env, profiling, "payloadBytesTotal", value); + napi_create_int64(env, static_cast(serializeUs), &value); + napi_set_named_property(env, profiling, "lastSerializeUs", value); + napi_create_int64(env, static_cast(payloadBytes), &value); + napi_set_named_property(env, profiling, "lastPayloadBytes", value); + napi_create_int64(env, static_cast(state.renderUpdateCalls), &value); + napi_set_named_property(env, profiling, "renderUpdateCalls", value); + napi_create_int64(env, static_cast(state.renderFrameUpdates), &value); + napi_set_named_property(env, profiling, "renderFrameUpdates", value); + napi_create_int64(env, static_cast(state.coreSyncCalls), &value); + napi_set_named_property(env, profiling, "coreSyncCalls", value); + napi_create_int64(env, static_cast(state.coreSyncSkipped), &value); + napi_set_named_property(env, profiling, "coreSyncSkipped", value); + napi_set_named_property(env, object, "napiProfiling", profiling); return object; } diff --git a/playback_lab/entry/src/main/cpp/harmony_playback_internal.h b/playback_lab/entry/src/main/cpp/harmony_playback_internal.h index c949b28a3a..9f363047ae 100644 --- a/playback_lab/entry/src/main/cpp/harmony_playback_internal.h +++ b/playback_lab/entry/src/main/cpp/harmony_playback_internal.h @@ -11,6 +11,20 @@ extern "C" { /* Private renderer bridge; never install this declaration as public API. */ mpv_handle *mp_harmony_playback_internal_handle(mp_harmony_player *player); +enum mp_harmony_internal_timeline_event { + MP_HARMONY_INTERNAL_RENDER_CONTEXT_READY = 1, + MP_HARMONY_INTERNAL_FIRST_VIDEO_FRAME, + MP_HARMONY_INTERNAL_FIRST_RENDER_BEGIN, + MP_HARMONY_INTERNAL_FIRST_RENDER_END, + MP_HARMONY_INTERNAL_FIRST_SWAP, + MP_HARMONY_INTERNAL_AUDIO_RENDERER_START, + MP_HARMONY_INTERNAL_FIRST_AUDIO_CALLBACK, + MP_HARMONY_INTERNAL_SEEK_FIRST_FRAME, + MP_HARMONY_INTERNAL_SEEK_FIRST_SWAP, +}; + +int mp_harmony_playback_internal_mark_timeline(mp_harmony_player *player, int event); + #ifdef __cplusplus } #endif diff --git a/playback_lab/entry/src/main/cpp/player.cpp b/playback_lab/entry/src/main/cpp/player.cpp index 15ed8cbff2..ac951507b1 100644 --- a/playback_lab/entry/src/main/cpp/player.cpp +++ b/playback_lab/entry/src/main/cpp/player.cpp @@ -1,6 +1,7 @@ #include "player.h" #include "video/harmony_hwdec.h" +#include "audio/out/ao_harmony.h" #include @@ -177,6 +178,8 @@ bool PlaybackEngine::load(const PlaybackRequestModel& request) std::lock_guard lock(mutex_); snapshot_.renderCount = 0; snapshot_.firstFrameMs = -1; + snapshot_.metrics = {}; + snapshot_.timeline = {}; startedAt_ = std::chrono::steady_clock::now(); } int rc = -1; @@ -184,7 +187,7 @@ bool PlaybackEngine::load(const PlaybackRequestModel& request) std::lock_guard apiLock(apiMutex_); if (corePlayer_ != nullptr) rc = mp_harmony_playback_load(corePlayer_, &coreRequest); } - syncCoreSnapshot(); + syncCoreSnapshot(true); return rc >= 0; } @@ -444,16 +447,64 @@ void PlaybackEngine::markFrameRendered() } } +uint64_t PlaybackEngine::sessionId() const +{ + return sessionIdAtomic_.load(std::memory_order_acquire); +} + +void PlaybackEngine::markRenderUpdate(bool frameAvailable) +{ + renderUpdateCalls_.fetch_add(1, std::memory_order_relaxed); + if (frameAvailable) renderFrameUpdates_.fetch_add(1, std::memory_order_relaxed); +} + +void PlaybackEngine::markTimeline(int event) +{ + std::lock_guard apiLock(apiMutex_); + if (corePlayer_ != nullptr) + mp_harmony_playback_internal_mark_timeline(corePlayer_, event); +} + +void PlaybackEngine::syncAudioTimeline() +{ + mpv_harmony_audio_stats audio = {}; + if (!mpv_harmony_audio_get_stats(&audio)) return; + if (audio.state == MPV_HARMONY_AUDIO_RUNNING) + markTimeline(MP_HARMONY_INTERNAL_AUDIO_RENDERER_START); + if (audio.callback_count > 0) + markTimeline(MP_HARMONY_INTERNAL_FIRST_AUDIO_CALLBACK); +} + PlaybackSnapshot PlaybackEngine::snapshot() const { + const_cast(this)->syncAudioTimeline(); const_cast(this)->syncCoreSnapshot(); std::lock_guard lock(mutex_); const_cast(this)->syncHwdecStatsLocked(); + const_cast(this)->snapshot_.renderUpdateCalls = + renderUpdateCalls_.load(std::memory_order_relaxed); + const_cast(this)->snapshot_.renderFrameUpdates = + renderFrameUpdates_.load(std::memory_order_relaxed); + const_cast(this)->snapshot_.coreSyncCalls = + coreSyncCalls_.load(std::memory_order_relaxed); + const_cast(this)->snapshot_.coreSyncSkipped = + coreSyncSkipped_.load(std::memory_order_relaxed); return snapshot_; } -void PlaybackEngine::syncCoreSnapshot() +void PlaybackEngine::syncCoreSnapshot(bool force) { + const auto now = std::chrono::steady_clock::now(); + { + std::lock_guard lock(syncThrottleMutex_); + if (!force && coreSyncHasRun_ && now - lastCoreSync_ < std::chrono::milliseconds(100)) { + coreSyncSkipped_.fetch_add(1, std::memory_order_relaxed); + return; + } + lastCoreSync_ = now; + coreSyncHasRun_ = true; + } + coreSyncCalls_.fetch_add(1, std::memory_order_relaxed); mp_harmony_playback_snapshot core = {}; mp_harmony_track coreTracks[MP_HARMONY_MAX_TRACKS] = {}; size_t coreTrackCount = 0; @@ -493,6 +544,7 @@ void PlaybackEngine::syncCoreSnapshot() snapshot_.state = mp_harmony_playback_state_name(core.state); snapshot_.sessionId = core.session_id; + sessionIdAtomic_.store(core.session_id, std::memory_order_release); snapshot_.position = core.position; snapshot_.duration = core.duration; snapshot_.fps = core.fps; @@ -544,6 +596,10 @@ void PlaybackEngine::syncCoreSnapshot() snapshot_.network.demuxer = core.network.demuxer; snapshot_.network.container = core.network.container; snapshot_.network.currentBitrate = core.network.current_bitrate; + snapshot_.metrics = core.metrics; + snapshot_.metrics.dropped_frames = core.dropped_frames; + snapshot_.metrics.render_count = static_cast(renderCount); + snapshot_.timeline = core.timeline; if (tracksAvailable) { snapshot_.tracks.clear(); diff --git a/playback_lab/entry/src/main/cpp/player.h b/playback_lab/entry/src/main/cpp/player.h index e5bf445d27..ea7a09e0fe 100644 --- a/playback_lab/entry/src/main/cpp/player.h +++ b/playback_lab/entry/src/main/cpp/player.h @@ -131,6 +131,12 @@ struct PlaybackSnapshot { int64_t nativeBufferImportFailure = 0; int64_t surfacePresentCount = 0; int64_t gpuInteropFrameCount = 0; + uint64_t renderUpdateCalls = 0; + uint64_t renderFrameUpdates = 0; + uint64_t coreSyncCalls = 0; + uint64_t coreSyncSkipped = 0; + mp_harmony_playback_metrics metrics = {}; + mp_harmony_playback_timeline timeline = {}; }; class PlaybackEngine { @@ -166,13 +172,17 @@ public: PlaybackSnapshot snapshot() const; mpv_handle* handle() const { return handle_; } + uint64_t sessionId() const; + void markRenderUpdate(bool frameAvailable); void markFrameRendered(); + void markTimeline(int event); private: void setState(const char* state); void setError(const std::string& error); void syncHwdecStatsLocked(); - void syncCoreSnapshot(); + void syncAudioTimeline(); + void syncCoreSnapshot(bool force = false); mutable std::mutex mutex_; mutable std::mutex apiMutex_; @@ -180,5 +190,13 @@ private: mp_harmony_player* corePlayer_ = nullptr; mpv_handle* handle_ = nullptr; std::atomic initialized_{false}; + std::atomic sessionIdAtomic_{0}; + std::atomic renderUpdateCalls_{0}; + std::atomic renderFrameUpdates_{0}; + std::atomic coreSyncCalls_{0}; + std::atomic coreSyncSkipped_{0}; + mutable std::mutex syncThrottleMutex_; + std::chrono::steady_clock::time_point lastCoreSync_; + bool coreSyncHasRun_ = false; std::chrono::steady_clock::time_point startedAt_; }; diff --git a/playback_lab/entry/src/main/cpp/render.cpp b/playback_lab/entry/src/main/cpp/render.cpp index bad7fc17e3..85c18ce960 100644 --- a/playback_lab/entry/src/main/cpp/render.cpp +++ b/playback_lab/entry/src/main/cpp/render.cpp @@ -217,19 +217,34 @@ void EglRenderer::renderLoop() return; } mpvStatus_.store(1); + player_.markTimeline(MP_HARMONY_INTERNAL_RENDER_CONTEXT_READY); + timelineSession_ = player_.sessionId(); + firstFramePending_ = true; mpv_render_context_set_update_callback(mpvRender_, onMpvUpdate, this); + auto lastUpdate = std::chrono::steady_clock::now(); while (!stop_.load()) { int width = 1; int height = 1; + bool shouldUpdate = false; { std::unique_lock lock(mutex_); wake_.wait_for(lock, std::chrono::milliseconds(16), [this] { return redraw_ || stop_.load(); }); + shouldUpdate = redraw_; redraw_ = false; width = width_; height = height_; } if (stop_.load()) break; + const auto now = std::chrono::steady_clock::now(); + if (!shouldUpdate && now - lastUpdate < std::chrono::milliseconds(250)) continue; + lastUpdate = now; + const uint64_t session = player_.sessionId(); + if (session != timelineSession_) { + timelineSession_ = session; + firstFramePending_ = true; + } uint64_t flags = mpv_render_context_update(mpvRender_); + player_.markRenderUpdate((flags & MPV_RENDER_UPDATE_FRAME) != 0); if ((flags & MPV_RENDER_UPDATE_FRAME) == 0) continue; mpv_opengl_fbo fbo = {0, width, height, GL_RGBA8}; int flip = 1; @@ -238,10 +253,21 @@ void EglRenderer::renderLoop() {MPV_RENDER_PARAM_FLIP_Y, &flip}, {MPV_RENDER_PARAM_INVALID, nullptr}, }; + const bool firstFrame = firstFramePending_; + if (firstFrame) { + player_.markTimeline(MP_HARMONY_INTERNAL_FIRST_VIDEO_FRAME); + player_.markTimeline(MP_HARMONY_INTERNAL_FIRST_RENDER_BEGIN); + } if (mpv_render_context_render(mpvRender_, renderParams) >= 0) { - eglSwapBuffers(display_, surface_); - mpv_render_context_report_swap(mpvRender_); - player_.markFrameRendered(); + if (firstFrame) player_.markTimeline(MP_HARMONY_INTERNAL_FIRST_RENDER_END); + if (eglSwapBuffers(display_, surface_) == EGL_TRUE) { + mpv_render_context_report_swap(mpvRender_); + if (firstFrame) { + player_.markTimeline(MP_HARMONY_INTERNAL_FIRST_SWAP); + firstFramePending_ = false; + } + player_.markFrameRendered(); + } } } mpv_render_context_set_update_callback(mpvRender_, nullptr, nullptr); diff --git a/playback_lab/entry/src/main/cpp/render.h b/playback_lab/entry/src/main/cpp/render.h index b9f36e7f82..0759fd8c0c 100644 --- a/playback_lab/entry/src/main/cpp/render.h +++ b/playback_lab/entry/src/main/cpp/render.h @@ -46,6 +46,8 @@ private: OHNativeWindow* window_ = nullptr; int width_ = 1; int height_ = 1; + uint64_t timelineSession_ = 0; + bool firstFramePending_ = true; EGLDisplay display_ = EGL_NO_DISPLAY; EGLContext context_ = EGL_NO_CONTEXT; EGLSurface surface_ = EGL_NO_SURFACE; diff --git a/playback_lab/entry/src/main/ets/pages/Index.ets b/playback_lab/entry/src/main/ets/pages/Index.ets index 6d33426cf6..e091ebf0ea 100644 --- a/playback_lab/entry/src/main/ets/pages/Index.ets +++ b/playback_lab/entry/src/main/ets/pages/Index.ets @@ -43,6 +43,8 @@ interface PlaybackState { errorCode: string; error: PlaybackErrorState; metrics: PlaybackMetricsState; + timeline: PlaybackTimelineState; + napiProfiling: NapiProfilingState; speed: number; volume: number; muted: boolean; @@ -54,6 +56,18 @@ interface PlaybackState { tracks: TrackState[]; } +interface NapiProfilingState { + getStateCalls: number; + serializeUsTotal: number; + payloadBytesTotal: number; + lastSerializeUs: number; + lastPayloadBytes: number; + renderUpdateCalls: number; + renderFrameUpdates: number; + coreSyncCalls: number; + coreSyncSkipped: number; +} + interface PlaybackErrorState { code: string; rawMessage: string; @@ -66,6 +80,50 @@ interface PlaybackMetricsState { cacheDuration: number; cacheBytes: number; currentBitrate: number; + bufferingEnterCount: number; + bufferingExitCount: number; + bufferingTotalMs: number; + bufferingMaxSingleMs: number; + networkWaitMs: number; + lateFrames: number; + mistimedFrames: number; + decoderFrames: number; +} + +interface PlaybackTimelineState { + sessionSetupMs: number; + mpvCreateMs: number; + mpvInitializeMs: number; + loadCommandMs: number; + startFileMs: number; + networkOpenBeginMs: number; + networkOpenEndMs: number; + firstByteMs: number; + demuxReadyMs: number; + fileLoadedMs: number; + videoDecoderReadyMs: number; + audioDecoderReadyMs: number; + videoReconfigMs: number; + audioReconfigMs: number; + renderContextReadyMs: number; + firstVideoFrameAvailableMs: number; + firstRenderBeginMs: number; + firstRenderEndMs: number; + firstSwapMs: number; + startupTotalMs: number; + audioRendererStartMs: number; + firstAudioCallbackMs: number; + playbackRestartMs: number; + seekRequestMs: number; + seekCommandMs: number; + seekDemuxMs: number; + seekVideoReconfigMs: number; + seekPlaybackRestartMs: number; + seekFirstFrameMs: number; + seekFirstSwapMs: number; + seekCommandLatencyMs: number; + seekRecoveryMs: number; + seekFirstVisibleFrameMs: number; } interface NetworkState { @@ -187,7 +245,19 @@ struct Index { nativeBufferImportCount: 0, nativeBufferImportFailure: 0, surfacePresentCount: 0, gpuInteropFrameCount: 0, sessionId: 0, errorCode: 'NONE', error: { code: 'NONE', rawMessage: '' }, - metrics: { droppedFrames: 0, renderCount: 0, buffering: false, cacheDuration: 0, cacheBytes: 0, currentBitrate: 0 }, + metrics: { droppedFrames: 0, renderCount: 0, buffering: false, cacheDuration: 0, cacheBytes: 0, currentBitrate: 0, + bufferingEnterCount: 0, bufferingExitCount: 0, bufferingTotalMs: 0, bufferingMaxSingleMs: 0, networkWaitMs: -1, + lateFrames: -1, mistimedFrames: -1, decoderFrames: -1 }, + timeline: { sessionSetupMs: -1, mpvCreateMs: -1, mpvInitializeMs: -1, loadCommandMs: -1, startFileMs: -1, + networkOpenBeginMs: -1, networkOpenEndMs: -1, firstByteMs: -1, demuxReadyMs: -1, fileLoadedMs: -1, + videoDecoderReadyMs: -1, audioDecoderReadyMs: -1, videoReconfigMs: -1, audioReconfigMs: -1, + renderContextReadyMs: -1, firstVideoFrameAvailableMs: -1, firstRenderBeginMs: -1, firstRenderEndMs: -1, + firstSwapMs: -1, startupTotalMs: -1, audioRendererStartMs: -1, firstAudioCallbackMs: -1, playbackRestartMs: -1, + seekRequestMs: -1, seekCommandMs: -1, seekDemuxMs: -1, seekVideoReconfigMs: -1, + seekPlaybackRestartMs: -1, seekFirstFrameMs: -1, seekFirstSwapMs: -1, seekCommandLatencyMs: -1, + seekRecoveryMs: -1, seekFirstVisibleFrameMs: -1 }, + napiProfiling: { getStateCalls: 0, serializeUsTotal: 0, payloadBytesTotal: 0, lastSerializeUs: 0, lastPayloadBytes: 0, + renderUpdateCalls: 0, renderFrameUpdates: 0, coreSyncCalls: 0, coreSyncSkipped: 0 }, speed: 1, volume: 100, muted: false, subtitleDelayMs: 0, subtitleScale: 1, subtitlePosition: 100, network: { protocol: '', host: '', networkState: '', httpStatus: 0, redirectCount: 0, @@ -205,7 +275,7 @@ struct Index { this.state = playbackLab.getState() as PlaybackState; this.status = this.state.state; this.detail = this.state.lastError || `position ${this.state.position.toFixed(2)} / ${this.state.duration.toFixed(2)}s`; - }, 250); + }, 500); } aboutToDisappear(): void { @@ -223,6 +293,12 @@ struct Index { .fontSize(13).fontColor($r('app.color.muted')).width('100%') Text(`error=${this.state.error.code} rawMessage=${this.state.error.rawMessage || 'none'}`) .fontSize(13).fontColor($r('app.color.muted')).width('100%').maxLines(3) + Text(`startup=${this.state.timeline.startupTotalMs}ms firstSwap=${this.state.timeline.firstSwapMs}ms seekRecovery=${this.state.timeline.seekRecoveryMs}ms audioStart=${this.state.timeline.audioRendererStartMs}ms audioCallback=${this.state.timeline.firstAudioCallbackMs}ms`) + .fontSize(13).fontColor($r('app.color.muted')).width('100%') + Text(`napi calls=${this.state.napiProfiling.getStateCalls} serialize=${this.state.napiProfiling.serializeUsTotal}us payload=${this.state.napiProfiling.payloadBytesTotal}B sync=${this.state.napiProfiling.coreSyncCalls}/${this.state.napiProfiling.coreSyncSkipped} updates=${this.state.napiProfiling.renderUpdateCalls}/${this.state.napiProfiling.renderFrameUpdates}`) + .fontSize(13).fontColor($r('app.color.muted')).width('100%').maxLines(2) + Text(`buffer enter=${this.state.metrics.bufferingEnterCount} exit=${this.state.metrics.bufferingExitCount} total=${this.state.metrics.bufferingTotalMs}ms max=${this.state.metrics.bufferingMaxSingleMs}ms networkWait=${this.state.metrics.networkWaitMs}ms`) + .fontSize(13).fontColor($r('app.color.muted')).width('100%').maxLines(2) XComponent({ id: 'playback_surface', type: XComponentType.SURFACE, libraryname: 'entry' }) .width('100%').height(250).backgroundColor(Color.Black) TextInput({ text: this.url, placeholder: 'file:///... or https://...' }) @@ -317,6 +393,10 @@ struct Index { Text(detailLabel(this.detail)).fontSize(13).fontColor($r('app.color.muted')).width('100%').maxLines(2) Text(`metrics dropped=${this.state.metrics.droppedFrames} renders=${this.state.metrics.renderCount} cache=${this.state.metrics.cacheDuration.toFixed(2)}s/${this.state.metrics.cacheBytes}B bitrate=${this.state.metrics.currentBitrate}`) .fontSize(13).fontColor($r('app.color.muted')).width('100%').maxLines(2) + Text(`buffer enter=${this.state.metrics.bufferingEnterCount} exit=${this.state.metrics.bufferingExitCount} total=${this.state.metrics.bufferingTotalMs}ms max=${this.state.metrics.bufferingMaxSingleMs}ms napi=${this.state.napiProfiling.getStateCalls}`) + .fontSize(13).fontColor($r('app.color.muted')).width('100%').maxLines(2) + Text(`render updates=${this.state.napiProfiling.renderUpdateCalls} frames=${this.state.napiProfiling.renderFrameUpdates} sync=${this.state.napiProfiling.coreSyncCalls}/${this.state.napiProfiling.coreSyncSkipped}`) + .fontSize(13).fontColor($r('app.color.muted')).width('100%').maxLines(2) Text('network=' + this.state.network.protocol + '://' + this.state.network.host + ' status=' + (this.state.network.httpStatus || 'unavailable') + ' redirects=' + this.state.network.redirectCount + ' buffering=' + this.state.network.buffering) .fontSize(13).fontColor($r('app.color.muted')).width('100%').maxLines(2) Text('range=' + this.state.network.rangeSupported + ' seek=' + (this.state.network.seekResult || 'unavailable')) diff --git a/player/harmony_playback.c b/player/harmony_playback.c index 8c1e23936a..4b869097bd 100644 --- a/player/harmony_playback.c +++ b/player/harmony_playback.c @@ -15,6 +15,7 @@ #include #include #include +#include struct mp_harmony_player { pthread_mutex_t lock; @@ -28,6 +29,9 @@ struct mp_harmony_player { int64_t playlist_entry_id; int awaiting_start; int64_t pending_start_position_ms; + int64_t perf_origin_ns; + int64_t buffering_start_ns; + int seek_active; mp_harmony_playback_snapshot snapshot; mp_harmony_track tracks[MP_HARMONY_MAX_TRACKS]; size_t track_count; @@ -42,8 +46,22 @@ enum { static int set_headers_locked(mp_harmony_player *p, const mp_harmony_playback_request *request); static int add_subtitle_locked(mp_harmony_player *p, const mp_harmony_subtitle_source *source); +enum mp_harmony_internal_timeline_event { + MP_HARMONY_INTERNAL_RENDER_CONTEXT_READY = 1, + MP_HARMONY_INTERNAL_FIRST_VIDEO_FRAME, + MP_HARMONY_INTERNAL_FIRST_RENDER_BEGIN, + MP_HARMONY_INTERNAL_FIRST_RENDER_END, + MP_HARMONY_INTERNAL_FIRST_SWAP, + MP_HARMONY_INTERNAL_AUDIO_RENDERER_START, + MP_HARMONY_INTERNAL_FIRST_AUDIO_CALLBACK, + MP_HARMONY_INTERNAL_SEEK_FIRST_FRAME, + MP_HARMONY_INTERNAL_SEEK_FIRST_SWAP, +}; + /* Private renderer bridge; intentionally absent from the public header. */ MP_HARMONY_EXPORT mpv_handle *mp_harmony_playback_internal_handle(mp_harmony_player *player); +MP_HARMONY_EXPORT int mp_harmony_playback_internal_mark_timeline( + mp_harmony_player *player, int event); static void copy_text(char *dst, size_t size, const char *src) { @@ -52,6 +70,91 @@ static void copy_text(char *dst, size_t size, const char *src) snprintf(dst, size, "%.*s", (int)(size - 1), src); } +static int64_t clock_now_ns(void) +{ + struct timespec now = {0}; + if (clock_gettime(CLOCK_MONOTONIC, &now) != 0) return 0; + return (int64_t)now.tv_sec * 1000000000LL + now.tv_nsec; +} + +static void reset_timeline(mp_harmony_playback_timeline *timeline) +{ + if (!timeline) return; + int64_t *values = (int64_t *)timeline; + for (size_t i = 0; i < sizeof(*timeline) / sizeof(*values); i++) values[i] = -1; +} + +static void reset_metrics(mp_harmony_playback_metrics *metrics) +{ + if (!metrics) return; + memset(metrics, 0, sizeof(*metrics)); + metrics->network_wait_ms = -1; + metrics->late_frames = -1; + metrics->mistimed_frames = -1; + metrics->decoder_frames = -1; +} + +static int64_t elapsed_ms_locked(const mp_harmony_player *p) +{ + if (!p || p->perf_origin_ns <= 0) return -1; + int64_t now = clock_now_ns(); + return now > p->perf_origin_ns ? (now - p->perf_origin_ns) / 1000000LL : 0; +} + +static void set_once(int64_t *value, int64_t timestamp) +{ + if (value && *value < 0 && timestamp >= 0) *value = timestamp; +} + +static int url_is_network(const char *url) +{ + return url && (strncasecmp(url, "http://", 7) == 0 || strncasecmp(url, "https://", 8) == 0); +} + +static void mark_timeline_locked(mp_harmony_player *p, int event) +{ + if (!p) return; + int64_t elapsed = elapsed_ms_locked(p); + mp_harmony_playback_timeline *t = &p->snapshot.timeline; + switch (event) { + case MP_HARMONY_INTERNAL_RENDER_CONTEXT_READY: + set_once(&t->render_context_ready_ms, elapsed); break; + case MP_HARMONY_INTERNAL_FIRST_VIDEO_FRAME: + set_once(&t->first_video_frame_available_ms, elapsed); + if (p->seek_active) set_once(&t->seek_first_frame_ms, elapsed); + break; + case MP_HARMONY_INTERNAL_FIRST_RENDER_BEGIN: + set_once(&t->first_render_begin_ms, elapsed); break; + case MP_HARMONY_INTERNAL_FIRST_RENDER_END: + set_once(&t->first_render_end_ms, elapsed); break; + case MP_HARMONY_INTERNAL_FIRST_SWAP: + set_once(&t->first_swap_ms, elapsed); + set_once(&t->startup_total_ms, elapsed); + if (p->seek_active) { + set_once(&t->seek_first_swap_ms, elapsed); + set_once(&t->seek_first_visible_frame_ms, elapsed); + if (t->seek_request_ms >= 0) + set_once(&t->seek_recovery_ms, elapsed - t->seek_request_ms); + p->seek_active = 0; + } + break; + case MP_HARMONY_INTERNAL_AUDIO_RENDERER_START: + set_once(&t->audio_renderer_start_ms, elapsed); break; + case MP_HARMONY_INTERNAL_FIRST_AUDIO_CALLBACK: + set_once(&t->first_audio_callback_ms, elapsed); break; + case MP_HARMONY_INTERNAL_SEEK_FIRST_FRAME: + set_once(&t->seek_first_frame_ms, elapsed); break; + case MP_HARMONY_INTERNAL_SEEK_FIRST_SWAP: + set_once(&t->seek_first_swap_ms, elapsed); + set_once(&t->seek_first_visible_frame_ms, elapsed); + if (t->seek_request_ms >= 0) + set_once(&t->seek_recovery_ms, elapsed - t->seek_request_ms); + p->seek_active = 0; + break; + default: break; + } +} + static int text_has(const char *text, const char *needle) { if (!text || !needle || !needle[0]) return 0; @@ -400,11 +503,25 @@ static void update_property_locked(mp_harmony_player *p, uint64_t id, mpv_event_ else if (id == PROP_SPEED && property->format == MPV_FORMAT_DOUBLE) p->snapshot.speed = *(double *)property->data; else if (id == PROP_TRACKS) refresh_tracks_locked(p); else if (id == PROP_CACHE_DURATION || id == PROP_CACHE_STATE || id == PROP_BUFFERING) { + int was_buffering = p->snapshot.metrics.buffering; update_network_locked(p); - if (id == PROP_BUFFERING && property->format == MPV_FORMAT_INT64) { - int64_t buffering = *(int64_t *)property->data; - if (buffering > 0) p->snapshot.state = MP_HARMONY_BUFFERING; - else if (p->snapshot.state == MP_HARMONY_BUFFERING) p->snapshot.state = MP_HARMONY_PLAYING; + int is_buffering = p->snapshot.metrics.buffering; + if (is_buffering != was_buffering) { + if (is_buffering) { + p->snapshot.metrics.buffering_enter_count++; + p->buffering_start_ns = clock_now_ns(); + p->snapshot.state = MP_HARMONY_BUFFERING; + } else { + p->snapshot.metrics.buffering_exit_count++; + if (p->buffering_start_ns > 0) { + int64_t duration = (clock_now_ns() - p->buffering_start_ns) / 1000000LL; + p->snapshot.metrics.buffering_total_ms += duration; + if (duration > p->snapshot.metrics.buffering_max_single_ms) + p->snapshot.metrics.buffering_max_single_ms = duration; + } + p->buffering_start_ns = 0; + if (p->snapshot.state == MP_HARMONY_BUFFERING) p->snapshot.state = MP_HARMONY_PLAYING; + } } } } @@ -415,9 +532,16 @@ static void handle_log_locked(mp_harmony_player *p, const mpv_event_log_message char redacted[MP_HARMONY_TEXT]; redact_text(redacted, sizeof(redacted), log->text); if (strstr(log->text, "HTTP/1.") || text_has(log->text, "http error")) { int status = 0; - if (sscanf(log->text, "%*[^0-9]%d", &status) == 1 && status >= 100 && status <= 599) { + const char *http = strstr(log->text, "HTTP/"); + if (http && sscanf(http, "HTTP/%*[^ ] %d", &status) == 1 && status >= 100 && status <= 599) { p->snapshot.network.http_status = status; if (status == 206) p->snapshot.network.range_supported = 1; + set_once(&p->snapshot.timeline.first_byte_ms, elapsed_ms_locked(p)); + if (p->snapshot.timeline.network_open_begin_ms >= 0) { + set_once(&p->snapshot.timeline.network_open_end_ms, elapsed_ms_locked(p)); + p->snapshot.metrics.network_wait_ms = + p->snapshot.timeline.first_byte_ms - p->snapshot.timeline.network_open_begin_ms; + } } } if (text_has(log->text, "redirect")) p->snapshot.network.redirect_count++; @@ -444,6 +568,9 @@ static void *event_loop(void *arg) mpv_event_start_file *start = event->data; p->awaiting_start = 1; if (start) p->playlist_entry_id = start->playlist_entry_id; + set_once(&p->snapshot.timeline.start_file_ms, elapsed_ms_locked(p)); + if (url_is_network(p->current_url)) + set_once(&p->snapshot.timeline.network_open_begin_ms, elapsed_ms_locked(p)); p->snapshot.state = MP_HARMONY_OPENING; break; } @@ -455,6 +582,17 @@ static void *event_loop(void *arg) if (loaded_url) mpv_free(loaded_url); if (!matches) break; p->awaiting_start = 0; + set_once(&p->snapshot.timeline.demux_ready_ms, elapsed_ms_locked(p)); + set_once(&p->snapshot.timeline.file_loaded_ms, elapsed_ms_locked(p)); + if (p->snapshot.timeline.network_open_begin_ms >= 0) { + set_once(&p->snapshot.timeline.network_open_end_ms, elapsed_ms_locked(p)); + if (p->snapshot.timeline.first_byte_ms >= 0) + p->snapshot.metrics.network_wait_ms = + p->snapshot.timeline.first_byte_ms - p->snapshot.timeline.network_open_begin_ms; + else + p->snapshot.metrics.network_wait_ms = + p->snapshot.timeline.network_open_end_ms - p->snapshot.timeline.network_open_begin_ms; + } refresh_media_locked(p); if (p->pending_start_position_ms >= 0) { char position[64]; @@ -475,6 +613,27 @@ static void *event_loop(void *arg) case MPV_EVENT_PROPERTY_CHANGE: update_property_locked(p, event->reply_userdata, event->data); break; + case MPV_EVENT_VIDEO_RECONFIG: + set_once(&p->snapshot.timeline.video_reconfig_ms, elapsed_ms_locked(p)); + set_once(&p->snapshot.timeline.video_decoder_ready_ms, elapsed_ms_locked(p)); + if (p->seek_active) set_once(&p->snapshot.timeline.seek_video_reconfig_ms, elapsed_ms_locked(p)); + break; + case MPV_EVENT_AUDIO_RECONFIG: + set_once(&p->snapshot.timeline.audio_reconfig_ms, elapsed_ms_locked(p)); + set_once(&p->snapshot.timeline.audio_decoder_ready_ms, elapsed_ms_locked(p)); + break; + case MPV_EVENT_SEEK: + if (p->seek_active) set_once(&p->snapshot.timeline.seek_demux_ms, elapsed_ms_locked(p)); + break; + case MPV_EVENT_PLAYBACK_RESTART: + set_once(&p->snapshot.timeline.playback_restart_ms, elapsed_ms_locked(p)); + if (p->seek_active) { + set_once(&p->snapshot.timeline.seek_playback_restart_ms, elapsed_ms_locked(p)); + if (p->snapshot.timeline.seek_request_ms >= 0) + set_once(&p->snapshot.timeline.seek_recovery_ms, + elapsed_ms_locked(p) - p->snapshot.timeline.seek_request_ms); + } + break; case MPV_EVENT_LOG_MESSAGE: handle_log_locked(p, event->data); break; @@ -515,6 +674,9 @@ mp_harmony_player *mp_harmony_playback_create(void) p->lock_ready = 1; p->snapshot.state = MP_HARMONY_IDLE; p->snapshot.error_code = MP_HARMONY_ERROR_NONE; p->snapshot.speed = 1.0; p->snapshot.volume = 100; p->snapshot.subtitle_scale = 1.0; p->snapshot.subtitle_position = 100.0; + reset_metrics(&p->snapshot.metrics); + reset_timeline(&p->snapshot.timeline); + p->pending_start_position_ms = -1; return p; } @@ -523,7 +685,10 @@ int mp_harmony_playback_initialize(mp_harmony_player *p) if (!p || !p->lock_ready) return -1; pthread_mutex_lock(&p->lock); if (p->initialized) { pthread_mutex_unlock(&p->lock); return 0; } + int64_t create_begin = clock_now_ns(); p->handle = mpv_create(); + if (create_begin > 0 && p->handle) + p->snapshot.timeline.mpv_create_ms = (clock_now_ns() - create_begin) / 1000000LL; if (!p->handle) { set_error_locked(p, MP_HARMONY_ERROR_UNKNOWN, "mpv_create failed"); pthread_mutex_unlock(&p->lock); return -1; } const char *options[][2] = { {"vo", "libmpv"}, {"terminal", "no"}, {"config", "no"}, {"hwdec", "no"}, @@ -537,7 +702,11 @@ int mp_harmony_playback_initialize(mp_harmony_player *p) pthread_mutex_unlock(&p->lock); return -1; } } - if (mpv_initialize(p->handle) < 0) { + int64_t initialize_begin = clock_now_ns(); + int initialize_result = mpv_initialize(p->handle); + if (initialize_begin > 0 && initialize_result >= 0) + p->snapshot.timeline.mpv_initialize_ms = (clock_now_ns() - initialize_begin) / 1000000LL; + if (initialize_result < 0) { set_error_locked(p, MP_HARMONY_ERROR_UNKNOWN, "mpv_initialize failed"); mpv_terminate_destroy(p->handle); p->handle = NULL; pthread_mutex_unlock(&p->lock); return -1; @@ -634,7 +803,16 @@ int mp_harmony_playback_load(mp_harmony_player *p, const mp_harmony_playback_req p->snapshot.subtitle_position = 100.0; p->snapshot.media = (mp_harmony_media_info){0}; p->snapshot.network = (mp_harmony_network_info){0}; - p->snapshot.metrics = (mp_harmony_playback_metrics){0}; + int64_t mpv_create_ms = p->snapshot.timeline.mpv_create_ms; + int64_t mpv_initialize_ms = p->snapshot.timeline.mpv_initialize_ms; + reset_metrics(&p->snapshot.metrics); + reset_timeline(&p->snapshot.timeline); + p->snapshot.timeline.mpv_create_ms = mpv_create_ms; + p->snapshot.timeline.mpv_initialize_ms = mpv_initialize_ms; + p->perf_origin_ns = clock_now_ns(); + p->snapshot.timeline.session_setup_ms = 0; + p->buffering_start_ns = 0; + p->seek_active = 0; p->snapshot.track_count = 0; p->track_count = 0; p->awaiting_start = 1; p->pending_start_position_ms = r->start_position_ms >= 0 ? r->start_position_ms : -1; copy_text(p->current_url, sizeof(p->current_url), r->url); @@ -674,6 +852,7 @@ int mp_harmony_playback_load(mp_harmony_player *p, const mp_harmony_playback_req else if (set_property_string(p, "sid", r->subtitle_enabled == 0 ? "no" : "auto") < 0) { pthread_mutex_unlock(&p->lock); return -1; } const char *args[] = {"loadfile", r->url, "replace", NULL}; int rc = mpv_command(p->handle, args); + set_once(&p->snapshot.timeline.load_command_ms, elapsed_ms_locked(p)); if (rc < 0) set_error_locked(p, classify_error(rc, mpv_error_string(rc)), mpv_error_string(rc)); if (rc >= 0) { for (size_t i = 0; i < r->subtitle_file_count; i++) { @@ -698,11 +877,26 @@ int mp_harmony_playback_seek(mp_harmony_player *p, mp_harmony_seek_mode mode, do if (!p || !isfinite(value) || mode < MP_HARMONY_SEEK_RELATIVE || mode > MP_HARMONY_SEEK_PERCENT) return -1; pthread_mutex_lock(&p->lock); if (ensure_ready_locked(p) < 0) { pthread_mutex_unlock(&p->lock); return -1; } + p->seek_active = 1; + p->snapshot.timeline.seek_request_ms = elapsed_ms_locked(p); + p->snapshot.timeline.seek_command_ms = -1; + p->snapshot.timeline.seek_demux_ms = -1; + p->snapshot.timeline.seek_video_reconfig_ms = -1; + p->snapshot.timeline.seek_playback_restart_ms = -1; + p->snapshot.timeline.seek_first_frame_ms = -1; + p->snapshot.timeline.seek_first_swap_ms = -1; + p->snapshot.timeline.seek_command_latency_ms = -1; + p->snapshot.timeline.seek_recovery_ms = -1; + p->snapshot.timeline.seek_first_visible_frame_ms = -1; char amount[64]; snprintf(amount, sizeof(amount), "%.6f", value); const char *kind = mode == MP_HARMONY_SEEK_ABSOLUTE ? "absolute" : (mode == MP_HARMONY_SEEK_PERCENT ? "absolute-percent" : "relative"); const char *flags = exact ? "exact" : (keyframe ? "keyframes" : NULL); const char *args[] = {"seek", amount, kind, flags, NULL}; int r = mpv_command(p->handle, args); + p->snapshot.timeline.seek_command_ms = elapsed_ms_locked(p); + if (p->snapshot.timeline.seek_request_ms >= 0 && p->snapshot.timeline.seek_command_ms >= 0) + p->snapshot.timeline.seek_command_latency_ms = + p->snapshot.timeline.seek_command_ms - p->snapshot.timeline.seek_request_ms; if (r >= 0) { p->snapshot.state = MP_HARMONY_SEEKING; copy_text(p->snapshot.network.seek_result, sizeof(p->snapshot.network.seek_result), "ok"); @@ -711,6 +905,7 @@ int mp_harmony_playback_seek(mp_harmony_player *p, mp_harmony_seek_mode mode, do redact_text(redacted, sizeof(redacted), mpv_error_string(r)); copy_text(p->snapshot.network.seek_result, sizeof(p->snapshot.network.seek_result), redacted); set_error_locked(p, MP_HARMONY_ERROR_SEEK, redacted); + p->seek_active = 0; } pthread_mutex_unlock(&p->lock); return r; } @@ -788,6 +983,19 @@ MP_HARMONY_EXPORT mpv_handle *mp_harmony_playback_internal_handle(mp_harmony_pla return handle; } +MP_HARMONY_EXPORT int mp_harmony_playback_internal_mark_timeline(mp_harmony_player *p, int event) +{ + if (!p) return -1; + pthread_mutex_lock(&p->lock); + if (ensure_ready_locked(p) < 0) { + pthread_mutex_unlock(&p->lock); + return -1; + } + mark_timeline_locked(p, event); + pthread_mutex_unlock(&p->lock); + return 0; +} + const char *mp_harmony_playback_state_name(mp_harmony_state state) { static const char *names[] = {"IDLE", "OPENING", "BUFFERING", "READY", "PLAYING", "PAUSED", "SEEKING", "ENDED", "STOPPED", "ERROR", "RELEASED"};