diff --git a/.agents/docs/2026-07-31-test-observability-implementation-plan.md b/.agents/docs/2026-07-31-test-observability-implementation-plan.md new file mode 100644 index 00000000..a4cf38c1 --- /dev/null +++ b/.agents/docs/2026-07-31-test-observability-implementation-plan.md @@ -0,0 +1,106 @@ +# `mcpp test` 可观测性与有界性 —— 实施计划 + +配套分析:[`2026-07-31-test-workspace-observability-analysis.md`](2026-07-31-test-workspace-observability-analysis.md) + +目标:把 `mcpp test` / `mcpp test --workspace` 从「不报时间、不设期限、还不 flush」变成一个**输出实时、耗时可信、墙钟有界、失败可归因**的操作。 + +三者互相耦合(分析 §6.3),因此**一个 PR 一起做**。 + +--- + +## S1 — stdout 实时性(根因:libc 缓冲区差 64 倍) + +**问题**:`ui::status/info/finished/plain` 与 `execute.cppm` 的测试结果行全是裸 `std::println(...)`,无一处 `fflush`;全仓库无 `setvbuf`。非 TTY 下缓冲区大小由 libc 决定 —— musl 固定 1 KB、Apple libc 取管道 `st_blksize`(64 KB)、MSVCRT 4 KB 且**不支持行缓冲**。同一份输出在三平台的可见时机差 64 倍,进程被 kill 时整段丢失。 + +**做法(两条腿,因为 setvbuf 在 Windows 上不成立)**: + +1. `mcpp::ui::set_line_buffered()`(POSIX 上 `setvbuf(_IOLBF)`),由 `main()` 调用 —— 兜住所有不走 ui 的直接输出。**不能放 `main.cpp` 里**:非模块 TU 不允许开 global module fragment 引 ``(Clang 直接拒绝,GCC 静默接受)。**Windows 上不调用**:UCRT 的 `size` 合法范围是 `2..INT_MAX`,0 会走 invalid-parameter handler 直接 abort(0xC0000409 → git-bash 报 exit 127),而 MSVCRT 本来就把 `_IOLBF` 当 `_IOFBF`,靠 `ui::flush()` 即可。 +2. `mcpp::ui` 新增 `flush()`,并在 **每个写 stdout 的 ui 函数**末尾调用(`status` / `info` / `finished` / `plain` / `diagnostic` 的 stdout 分支)。这条在 Windows 上也确定有效,不依赖 `_IOLBF` 语义。 +3. `execute.cppm` 中 `mcpp test` 的裸 `std::println` 结果行(`... ok` / `FAIL (...)`)改走 `ui::plain`,从而继承 flush。 + +**验收**:e2e 断言 —— `mcpp test --workspace` 的 stdout 重定向到管道时,**逐行到达**(在扇出中途读到第一个成员的 `test result`,而不是等进程退出)。 + +--- + +## S2 — `--timeout` 有界化 + +**问题**:`TestOptions::timeoutSecs = 0`(不限)是默认值,`mcpp test` 因此不是有界操作。 + +**做法**:默认改 **300 秒**;`--timeout 0` 显式表示不限。help / `docs/` 同步。 + +**验收**:单测 + e2e(一个 `sleep` 测试在 `--timeout 1` 下报 `FAIL (timeout after 1s)` 且扇出继续)。 + +--- + +## S3 — `--build-timeout`(唯一能兜住链接卡死的闸) + +**问题**:`--timeout` 只包住测试进程的**运行**。三处 `backend->build()`(`execute.cppm:1056` Phase A / `:1103` bulk / `:1126` per-test)全无期限。macOS 上 `modules/jsc` 卡在 14 次可执行链接上,`--timeout` 设多少都无效。 + +**做法**: +- `BuildOptions` 加 `buildTimeoutSecs`(0 = 不限,**默认 0 —— 见下**)。 +- `ninja_backend` 把 `capture_exec` 换成 `capture_exec_deadline`,超时返回 `BuildError{"build timed out after Ns", ...}`。 +- `run_tests` 三处 build 各自独立计时;超时报成**该成员的构建失败**,扇出继续下一个成员。 +- **平台限制如实写明**:`capture_exec_deadline` 在 Windows 上忽略 deadline(`process.cppm:96-99`),因此 `--build-timeout` 目前是 POSIX-only。文档标注,不假装跨平台。 + +**默认为什么是关的**(与 `--timeout` 不对称,实测而非风格):单个测试跑过 5 分钟不寻常,冷依赖构建跑过 15 分钟很平常 —— mcpp-index 有成员要从源码建 OpenCV,linux 1019s / windows 1289s。默认上限会把「慢但正确」的构建判红。构建能跑多久是工程的性质,由工程来说。 + +**验收**:e2e —— 一个故意慢的编译边在 `--build-timeout 1` 下被判超时且信息里带成员名。 + +--- + +## S4 — 耗时数字可信 + +**问题 A**:`auto t0` 在 `execute.cppm:1107`,即 Phase A + bulk build **之后**才起表,`finished in` 只覆盖 per-test 循环。实测 `modules/jsc` 打印 `6.53s`、真实 `93.5s`,**误差 14.3×**。 + +**问题 B**:per-test 耗时已在 `TestResult::durationMs` 里,但**只发给 JSON**,human 模式的 `t1 ... ok` 不带时间。 + +**做法**: +- `t0` 移到 Phase A 之前;分别累计 `buildMs`(Phase A + bulk + per-test build)与 `runMs`。 +- 汇总行:`test result ok. 14 passed; 0 failed; finished in 93.5s (build 87.0s + run 6.5s)`。 +- per-test human 行带时间:`t1 ... ok (0.31s)` / `t1 ... FAIL (exit 1, 2.40s)`。 + +--- + +## S5 — 扇出层可观测性 + +**问题**:97 个成员串行,过程中唯一线索是 `Workspace testing member 'X'`。无 `M/N`、无 per-member 耗时、无累计耗时、无 workspace 级汇总。 + +**做法**: +- `run_tests` 返回结构化结果(新增 `TestRunSummary{passed, failed, elapsed, buildMs, runMs}`),而不是只回 `int`。 +- 扇出打: + ``` + Workspace member 'modules/jsc' (23/97) ok — 14 passed in 93.5s + workspace result ok. 97 members; 412 passed; 0 failed; finished in 355.2s + slowest: modules/jsc 93.5s, modules/install 32.2s, modules/http_types 24.1s + ``` +- 失败时同样带耗时与 `M/N`。 + +--- + +## S6 — `--workspace-timeout` + +整条扇出的累计墙钟上限(默认 0 = 不限,由 CI 的 `timeout-minutes` 兜底)。超时后**停止扇出**,如实汇总已完成成员、列出未跑成员,退出码非零 —— 而不是被外部 SIGKILL 掉、连汇总都拿不到。 + +--- + +## S7 — JSON 输出契约(分析 §4) + +1. **表头不再污染 stdout**:`--message-format json` 时,扇出层在调用 `run_tests` **之前**就 `set_quiet(true)`(现在是第一个成员漏出去、第二个起被静音)。 +2. **测试名带成员**:每条 test 记录加 `"member"` 字段。 +3. **workspace 级 summary**:`{"workspace_summary":{"members":N,"passed":P,"failed":F,"elapsed_ms":E}}`。 + +--- + +## S8 — macOS `runtime_library_path_key() == ""` 的静默差异 + +`platform/env.cppm:163` 在 macOS 返回空串(理由正确:`DYLD_LIBRARY_PATH` 会波及 ninja 启动的每个可执行文件)。后果是依赖 `[runtime] library_dirs` 的测试在 Linux/Windows 过、macOS 以 dyld 错误失败,且**零诊断**。 + +**做法**:`run_tests` 在 macOS 上若 `plan.runtimeLibraryDirs` 非空而注入键为空,发一条 `diag::warning`,点名这条平台差异与 rpath 兜底。 + +--- + +## 落地顺序 + +S1 → S2 → S4 → S5 → S7 → S3 → S6 → S8,每步自带测试。 + +版本:`2026.8.1.1`(`2026.7.31.1` 已发布)。真源 `src/toolchain/fingerprint.cppm::MCPP_VERSION` + `mcpp.toml`,由 `.github/tools/check_version_pins.sh` 机器校验。 diff --git a/.agents/docs/2026-07-31-test-workspace-observability-analysis.md b/.agents/docs/2026-07-31-test-workspace-observability-analysis.md new file mode 100644 index 00000000..b39138f9 --- /dev/null +++ b/.agents/docs/2026-07-31-test-workspace-observability-analysis.md @@ -0,0 +1,301 @@ +# `mcpp test --workspace`:跨平台模型一致性、输出差异与 macOS 停滞的根因分析 + +**分析对象**:mcpp `2026.7.31.1`(HEAD `0547324`)源码,+ Sunrisepeak/mbun CI(97 个 workspace 成员)三平台实测,+ mcpp-index CI 30 次运行横向对照,+ 本机 strace 复现。 + +**结论全部经实测,推断部分单独标注。** + +> **状态**:本文描述的是 `2026.7.31.1` 及之前的行为。§7.1 列出的 mcpp 侧改动已在 **2026.8.1.1** 全部实现 +> (实施计划见 [`2026-07-31-test-observability-implementation-plan.md`](2026-07-31-test-observability-implementation-plan.md), +> 回归锁在 `tests/e2e/178_test_observability.sh` 与 `tests/unit/test_test_options.cpp`)。 +> §7.2 的 mbun 侧与 §7.3 的两项待验证仍然开放。 + +--- + +## 0. 结论速览 + +| 问题 | 结论 | +|---|---| +| 编排/实现是同一个模型吗? | **是**。`--workspace` 扇出是一段纯 C++ 串行循环,三平台同一条路径,零平台分支。 | +| 执行是同一个模型吗? | **基本是**。只有 3 处平台分支,其中 macOS 的 `runtime_library_path_key()` 返回空串是唯一语义级差异。 | +| 输出是同一个模型吗? | **不是**,而且有两类原因:①`--workspace` 自身的 3 个输出契约缺口(§4);②**Linux/macOS 链接的 libc 不同,stdio 缓冲区差 64 倍**(§5.5)。②才是"连打印都不一样"的真因。 | +| macOS 慢非常多? | **前 21 个成员 macOS 比 Linux 快 2.1×**,然后在 `modules/jsc` 上 ≥25× 并被 CI 杀掉。**不是平台常数慢,是单个成员的链接阶段炸了。** | +| mcpp 有责任吗? | 有三条,且互相耦合:**stdout 不 flush**(诊断全丢)、**`--timeout` 兜不住构建**(卡在链接时形同虚设)、**扇出层零计时零进度**(无法归因)。见 §6。 | + +--- + +## 1. 实现:`--workspace` 到底做了什么 + +入口 `src/cli/cmd_build.cppm:29 workspace_fanout_members()` + `:165 cmd_test()`。 + +扇出条件(build/test 共用同一判据):显式 `--workspace`,**或**处在 *virtual* workspace 根(`[package].name` 为空)且没给 `-p`。 + +扇出体(`cmd_build.cppm:165-185`): + +``` +for member in members: # 严格串行 + ui::status("Workspace", "testing member 'X'") + rc |= run_tests(passthrough, {package_filter = member}, testOpts) +汇总: "all N member(s) passed" / "workspace test: k/N member(s) failed: ..." +``` + +即 **`mcpp test --workspace` ≡ 对每个成员依次执行一次完整的 `mcpp test -p `**,continue-on-failure,首个非零退出码胜出。这段没有任何 `#if` / `is_windows` / `is_macos`。 + +每成员内部(`execute.cppm:828 run_tests`)固定 7 步: + +1. `find_manifest_root` → `resolve_member_dir()` 把发现范围**收敛到成员目录**(否则各成员的 `tests/main.cpp` 会撞名)。 +2. `expand_glob(memberDir, "tests/**/*.cpp")`;`expand_glob_one` 内部 `std::sort` + canonical 去重(`scanner.cppm:458`)⇒ **发现顺序三平台确定且一致**,不依赖目录遍历顺序。 +3. 每个测试文件合成一个 `Target{kind = TestBinary}`,名字 = 相对 `tests/` 去扩展名的路径。 +4. `prepare_build(includeDevDeps = true, extraTargets = 合成目标)` —— **每成员一次完整解析**(重新 resolve 工具链、重新合并 workspace deps/indices、重新算指纹目录)。 +5. **Phase A**:一次 ninja,目标 = 所有非测试编译单元 + 非测试链接产物。此处失败报成*包*级错误,而非 N 个红测试。 +6. **Phase B**:先一次 `-k 0` 批量 ninja 并行建出所有测试目标;再**逐测试**重新驱动 ninja(成功者为 no-op)以获得干净归因;然后逐个 exec 运行。 +7. 汇总打印。 + +### 1.1 实测的进程模型(本机 strace) + +2 成员 × 4 测试 + `import std` + `llvm@20.1.7`: + +``` +ninja 调用 = 12 = 2 成员 × (1 PhaseA + 1 bulk + 4 per-test) +clang++ = 28 +clang-scan-deps = 10 +/bin/sh = 54 ← Clang 的 .pcm restat 包装(cp -p / cmp -s) +execve 总计 = 175 +``` + +⇒ **ninja 进程数 = Σ_member (2 + tests(member))**。热跑重测:12 次 ninja、**0 次重新链接** —— per-test 重驱动确实是 no-op,**不是性能问题**。(曾怀疑它每个测试重链一次,逐行核对 strace 后证伪:成对出现的 `-o bin/tN` 是 `clang++` 驱动 + 它 exec 出的 `ld.lld`,同一次链接。) + +--- + +## 2. 三平台共享的部分 + +- 扇出循环、成员解析、测试发现与命名、两阶段构建、结果收集与汇总:**全部平台无关**。 +- 输出目录 `target///`:同一套规则。 +- `mcpp test -p X`(从 workspace 根)与 `cd X && mcpp test` **最终收敛到同一状态**:`prepare.cppm:772-806` 与 `:807-827` 两分支都做 `merge_workspace_deps` / 继承 `[toolchain]` / `inherit_workspace_indices`,并把 `root` 落到成员目录。唯一差别是前者多打一行 `Workspace building member 'X'`。 + +--- + +## 3. 三平台**不**一样的部分(执行层,共 3 处) + +| 位置 | Linux | macOS | Windows | +|---|---|---|---| +| `platform/env.cppm:163 runtime_library_path_key()` | `LD_LIBRARY_PATH` | **`""`(空)** | `PATH` | +| `execute.cppm:1160` 注入 sandbox `subos/default/bin` 到子进程 `PATH` | 有 | 有 | **无** | +| `plan.cppm:241` / `ninja_backend.cppm:169` rpath / soname | `-Wl,-rpath,'$ORIGIN'` / `-soname` | `-Wl,-rpath,@loader_path` / `-install_name,@rpath/` | 无 rpath(靠 DLL 拷贝) | + +第一处是**语义级**差异:`run_tests`(`execute.cppm:1109-1155`)用 `runtime_library_path_key()` 决定给测试子进程注入什么运行期库路径。**macOS 返回空串,`childEnv` 里根本没有这一项**,完全依赖链接期 rpath。注释写明了理由(`DYLD_LIBRARY_PATH` 会波及 ninja 启动的每个可执行文件,可能让系统框架加载到私有 libc++/libc++abi)——取舍正确,但后果是"依赖 `[runtime] library_dirs` 才能跑起来"的测试在 Linux/Windows 过、在 macOS 以 dyld 错误失败,**且没有任何诊断说出这条差异**。 + +除此之外,`mcpp test` 路径上没有其他平台条件分支。 + +--- + +## 4. 输出契约的 3 个缺口(与平台无关) + +本机实跑 `mcpp test --workspace --message-format json`,原样输出: + +``` + Workspace testing member 'a' ← ① 非 JSON 行混进 stdout +{"test":"t1",...} +{"summary":{"passed":4,"failed":0,"elapsed_ms":37}} ← ③ 第一个 summary +{"test":"t1",...} ← ② 又一个 "t1",无法区分成员 +{"summary":{"passed":4,"failed":0,"elapsed_ms":47}} ← ③ 又一个,且无 workspace 级 summary +``` + +① **JSON 模式下 stdout 被污染,且不对称**。`run_tests` 进入时才 `set_quiet(true)`(`execute.cppm:834`),而 `Workspace testing member` 由 `cmd_test` 在调用**之前**打 ⇒ 第一个成员的表头漏出去,第二个起被静音。 + +② **测试名不带成员前缀**。`t1` 可能在 96 个成员里各出现一次,消费者无法归因。 + +③ **每成员各发一条 `summary`,无 workspace 级 summary**。human 模式的 `all N member(s) passed` 在 JSON 里没有对应记录;失败列表只走 `ui::error` → stderr。 + +--- + +## 5. macOS:测量与归因 + +### 5.1 先澄清:mbun 两条 lane 跑的根本不是同一个命令 + +- `macos-probe` 的 Test 步 = `mcpp test --workspace`(mcpp 原生扇出输出)。 +- `build-test (llvm@22.1.8)` 的 Test 步 = `tools/integration/test_members.sh`,内部 `(cd $member && mcpp test) > $log 2>&1`,**按设计静默**,且 `SKIP_MEMBERS="modules/jsc"`。实测该步日志 `11:24:43`→`11:27:17`,**输出零行**。 + +⇒ 两条 lane 的输出差异,一部分直接来自 mbun 用了两个不同驱动。属于 mcpp 的部分是 §4 与 §5.5。 + +### 5.2 实测数字(同一 commit,97 个成员) + +run `30631334192`,commit `a054786`: + +| 步骤 | linux gcc@16.1.0(4 核) | linux llvm@22.1.8 | **macOS arm64 llvm@20.1.7(3 核)** | +|---|---|---|---| +| `mcpp build --workspace` | 646 s | 304 s | **399 s** | +| `mcpp run -- --version` | 322 s | (skipped) | **153 s** | +| `mcpp test --workspace` | **355 s(跑完)** | 154 s(跳过 jsc) | **≥2713 s,被 45 min step timeout 杀掉** | + +### 5.3 归因:不是平台常数慢,是单个成员的链接炸了 + +用**子测试进程的输出**(它们是独立进程、退出时各自 flush,时间戳可信)做 landmark: + +| landmark | macOS | linux gcc | +|---|---|---| +| Test 步开始 | 12:47:35 | 12:47:14 | +| `test_dependency: 86 checks`(`modules/install` 最后一个测试) | 12:48:21 = **T+46 s** | **T+98 s** | +| 之后 | **44 m 27 s 零输出**,13:32:48 被杀 | `modules/js` 12.4 s + `modules/jsc` 93.5 s,全程 355 s 跑完 | + +⇒ **前 21 个成员 macOS 比 Linux 快 2.1×**;紧接着的成员上 Linux 106 s、macOS ≥2667 s ⇒ **≥25×**。 + +**卡点是 `modules/jsc`**,规模(从 Linux 日志数出):**32 个 path 依赖** + `mbun.jsc-prebuilt`(预编 JavaScriptCore)+ **14 个 test 可执行文件**,每个都要链到这一整坨。 + +决定性佐证 —— 同一 macOS job 的 Build 步里,`modules/jsc` **只发了一条边**: + +``` +llvm-ar rcs bin/libjsc.a ← 零个可执行链接,145 s 就过了 +``` + +`mcpp build` 对这个成员只打包静态库;`mcpp test` 才**把 14 个可执行文件分别链到整个预编 JSC 上**,dev profile 是 `-O0 -g`。**差异面是链接,不是编译** —— 这就是"Build 步 macOS 只慢 1.31×、Test 步炸掉"的全部原因。 + +macOS 侧链接为何这么贵(**推断**,按可信度排): +1. Apple `ld` 在 `-g` 下要建 **debug map**,读进每个被拉入 object 的 DWARF;Linux 的 lld/bfd 不做这步,DWARF 留在 `.o` 里。对着几百 MB 静态归档 ×14 次。 +2. arm64 上每个可执行文件链接时**强制 ad-hoc 签名**,哈希整个二进制每一页。 +3. macOS runner 3 核 vs Linux 4 核(常数,非主因)。 + +**横向对照**:mcpp-index 仓库(46 个成员,同样 `mcpp test --workspace`)最近 30 次 CI 里 **macOS 每一次都是三平台最快**(2446 s vs linux 4685 s / windows 4535 s),逐成员对比无一例外。⇒ 不存在"macOS 上 `mcpp test --workspace` 普遍慢"这回事。 + +### 5.4 为什么 Linux 的 Test 步看得到构建信息、macOS 完全看不到 + +**这不是代码差异,是两个平台链接的 libc 不同。** + +`ui::status / info / finished / plain`(`ui.cppm:228/241/253/293`)全是裸 `std::println(...)`,**无一处 `fflush`**;全仓库**无 `setvbuf`**。所以非 TTY 下 stdout 全缓冲,**缓冲区大小由 libc 决定**: + +| | Linux 发行版二进制 | macOS 发行版二进制 | +|---|---|---| +| 链接方式 | **musl 静态链接**(`file` 实测 `statically linked`) | Mach-O,动态链接 Apple libSystem | +| stdio 缓冲区 | musl **写死 `BUFSIZ = 1024`**,不看 `st_blksize` | BSD stdio 取 `fstat(1).st_blksize`;CI 里 stdout 是管道,macOS 管道报 **65536**(*待在 runner 上一条命令确认*) | + +本机 strace 实测 Linux 侧(30 成员 workspace): + +``` +write(1, …) = 34, 1048, 1027, 1030, 1030, 1055, 1083, 1083, 1083, 1083, 1083, 228 +``` + +全部 ~1024。**而本机管道的 `st_blksize` 是 4096,mcpp 照样按 1024 走** ⇒ 坐实是 musl 的固定值,不是从 OS 取的。 + +对上实际现象 —— 从 Test 步开始到 `test_dependency`(macOS 停住的同一点),mcpp 自身输出量 **13 639 B ≈ 13.3 KB**: + +- **Linux(1 KB 缓冲)**:13.3 KB ÷ 1 KB ≈ **13 次 flush** → 边跑边一块块吐出,与子进程输出交错。铁证是这一行: + ``` + Workspace testing member 'modules/semver' huge prefix runs: 12 ms + ``` + mcpp 的行还没写到换行符,1 KB 边界就到了被冲出去,子进程输出紧跟着落在同一行 —— **只有定长块 flush 会长这样,行缓冲永远不会**。 +- **macOS(64 KB 缓冲)**:13.3 KB ÷ 64 KB = **0 次 flush** → 一行 mcpp 输出都没出来;45 min 后 step timeout **SIGKILL**,缓冲区连同 13.3 KB 一起丢弃。 + +而两边都能实时看到 `test_core_alloc: 128 checks` —— 那是**子测试进程**,独立进程各自退出时 flush,直接落到同一个 fd 1,与 mcpp 的缓冲区无关。 + +这也解释了 macOS 的 **Build 步为何正常**:`mcpp build --workspace --verbose` 把 ninja 输出也走 stdout,几百 KB,轻松反复越过 64 KB 阈值。**不是 test 与 build 的代码不同,是输出量跨没跨过阈值。** + +**验证命令(在 macOS runner 上)**: +```bash +python3 -c "import os;print(os.fstat(1).st_blksize)" # 管道里跑,预期 65536 +script -q /dev/null mcpp test --workspace # 伪 TTY → 行缓冲 → 立刻实时输出 +``` + +--- + +## 6. 计时与超时:现状缺陷 + 建议补充的功能 + +### 6.1 现状(全部经代码 + CI 日志核对) + +| 能力 | 现状 | 位置 | +|---|---|---| +| 单测试耗时 | **测了但只发给 JSON**。`TestResult::durationMs` 由 `test_ms()` 填,`emit_json` 发 `duration_ms`;human 模式的 `t1 ... ok` **不带时间** | `execute.cppm:1010,1117,1028` | +| 单成员总耗时 | 打印 `test result ok. N passed; 0 failed; finished in X.XXs`,**但起表点是错的** | `execute.cppm:1107,1228` | +| workspace 总耗时 | **完全没有**。扇出只打 `all N member(s) passed` | `cmd_build.cppm:176-183` | +| 单测试超时 | `--timeout N` 有,**默认 0 = 不限** | `execute.cppm:801` | +| 构建超时 | **没有** | — | +| workspace 总超时 | **没有** | — | + +**缺陷 A —— `finished in` 漏算构建时间。** `auto t0` 在 `execute.cppm:1107`,即 **Phase A(包级构建)与 Phase B 批量构建都跑完之后**才起表,只覆盖 per-test 循环。CI 实测: + +| 成员 | 打印值 | 真实墙钟 | 误差 | +|---|---|---|---| +| `modules/jsc` | `finished in 6.53s` | 93.5 s | **14.3×** | +| `modules/install` | `finished in 33.02s` | 32.2 s | ~1× | + +差别在于时间花在哪:`install` 主要在 per-test 循环里(算得进),`jsc` 的 87 秒全在 Phase A + 批量构建(**完全不算**)。⇒ **越是构建重的成员,这个数字越不可信** —— 恰好是最需要它的时候。 + +**缺陷 B —— `--timeout` 兜不住构建。** + +``` +execute.cppm:1056 backend->build(Phase A) ← 无期限 +execute.cppm:1103 backend->build(bulk) ← 无期限 +execute.cppm:1126 backend->build(per-test) ← 无期限 +execute.cppm:1181 capture_exec_deadline(...) ← 只有这里受 --timeout 约束 +execute.cppm:1186 run_exec_deadline(...) ← 只有这里受 --timeout 约束 +``` + +⇒ **macOS 那次卡在 `modules/jsc` 的链接上,`--timeout` 设多少都救不了。** + +**缺陷 C —— 扇出层零可观测性。** 97 个成员串行,过程中唯一线索是 `Workspace testing member 'X'` 一行(而在 §5.4 的缓冲问题下 macOS 上根本出不来)。没有 `M/N` 进度、没有 per-member 耗时、没有累计耗时 ⇒ 这次定位 `modules/jsc` 只能靠反解 GitHub 日志时间戳。 + +### 6.2 建议补充的功能 + +**计时(3 项)** + +1. **per-test 耗时进 human 输出**:`t1 ... ok (0.31s)` / `t1 ... FAIL (exit 1, 2.40s)`。数据已在 `durationMs` 里,只差打出来。 +2. **修 `t0` 起表点,并拆两段**:起表移到 Phase A 之前,汇总行改成 + `test result ok. 14 passed; 0 failed; finished in 93.5s (build 87.0s + run 6.5s)`。 + 构建/运行分开远比一个合并数字有用 —— `jsc` 这种 93% 时间在链接的成员一眼可见。 +3. **workspace 级汇总 + 进度**: + ``` + Workspace member 'modules/jsc' (23/97) ok — 14 passed in 93.5s + workspace result ok. 97 members; 412 passed; 0 failed; finished in 355.2s + slowest: modules/jsc 93.5s, modules/install 32.2s, modules/http_types 24.1s + ``` + JSON 模式补 `{"workspace_summary":{"members":97,"passed":412,"failed":0,"elapsed_ms":355200}}`,并给每条 test 记录加 `"member"` 字段(解决 §4 ②)。 + +**超时(3 层,语义必须分清)** + +| 开关 | 约束对象 | 建议默认 | 触发时 | +|---|---|---|---| +| `--timeout ` | 单个测试**进程的运行** | **300**(现为 0=不限) | `FAIL (timeout after Ns)`,继续下一个测试 | +| `--build-timeout ` | **单条 ninja 驱动**(Phase A / bulk / per-test 各自独立计) | 900 | 报成该成员的 `build timeout`,继续下一个成员 —— **唯一能兜住 macOS 那种链接卡死的闸** | +| `--workspace-timeout ` | **整条扇出**的累计墙钟 | 0(不限,由 CI `timeout-minutes` 兜底) | 停止扇出,**如实汇总已完成成员**并列出未跑的,退出码非零 | + +三条硬要求: + +- **超时必须能归因**:报文带 ` / / `,而不是只有 "timed out"。 +- **超时触发时必须 `fflush(stdout)`**:否则在 macOS 上(§5.4)这条报告本身也会被吞掉。 +- **`--timeout 0` 显式表示"不限"**,默认必须有界 —— `mcpp test` 才是一个能放进 CI 的操作。 + +### 6.3 为什么这一组是同一件事 + +本次排查的全部困难来自同一个缺口:**`mcpp test --workspace` 既不报时间、也不设期限、还不 flush**。三者任缺其一,另外两个的价值都打折: + +- 只加超时不修 `setvbuf` ⇒ 超时报告被缓冲区吞掉,CI 上仍是一片空白; +- 只加计时不加超时 ⇒ 知道谁慢,但仍会被 CI 的 `timeout-minutes` SIGKILL,连汇总都拿不到; +- 只修 flush 不加计时 ⇒ 看得到卡在哪个成员,但不知道正常该多久、慢了多少倍。 + +建议作为**一个 PR** 一起做。 + +--- + +## 7. 行动项 + +### 7.1 mcpp 侧(按性价比排序) + +| # | 改动 | 规模 | 解决 | +|---|---|---|---| +| 1 | `std::setvbuf(stdout, nullptr, _IOLBF, 0)` 于 `main.cpp` 入口 | 1 行 | 跨平台输出行为统一;被 kill 时不丢诊断;mcpp 的行不再被从中间切开 | +| 2 | `--build-timeout`(包住三处 `backend->build`) | 中 | 链接/编译卡死可归因、可继续 | +| 3 | `--timeout` 默认改 300,`0` 显式表示不限 | 小 | `mcpp test` 成为有界操作 | +| 4 | per-test 耗时进 human 输出 + 修 `t0` 起表点(build/run 分列) | 小 | 数字可信 | +| 5 | 扇出层 per-member 计时 + `M/N` 进度 + workspace 级汇总(human & JSON) | 中 | 可观测性 | +| 6 | JSON 模式:表头改成 JSON 记录 / 提前 `set_quiet`;测试名加成员前缀 | 小 | §4 ①② | +| 7 | `--workspace-timeout` | 中 | 兜底 | +| 8 | macOS `runtime_library_path_key() == ""` 时,若成员声明了 `[runtime] library_dirs` 给一条诊断 | 小 | §3 静默差异 | + +### 7.2 mbun 侧 + +- **`--timeout` 对本次问题无效**(卡在链接,不在运行)—— 需要 mcpp 的 `--build-timeout`,或先在 macOS lane 也 `SKIP_MEMBERS="modules/jsc"`。 +- 对 `modules/jsc` 用 release profile(去掉 `-g` 能砍掉 macOS debug map 的大头),这是当前唯一不改 mcpp 就能试的解法。 +- macOS lane 与 llvm lane 对齐驱动:要么都用 `mcpp test --workspace`,要么都用 `test_members.sh`。现在的不对称本身就是"输出不一样"的来源之一。 + +### 7.3 待验证(唯一还没实测的两点) + +1. macOS runner 上 `python3 -c "import os;print(os.fstat(1).st_blksize)"`(管道内)是否为 65536 —— 确认 §5.4 的缓冲区数字。 +2. macOS 上单跑 `mcpp test -p modules/jsc`,看时间是否几乎全在 14 次可执行链接上(`-O0 -g` vs `--release` 对照)—— 确认 §5.3 的链接归因。 diff --git a/CHANGELOG.md b/CHANGELOG.md index 2eb47a7c..ca4eb5c3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,47 @@ > 本文件追踪 `mcpp-community/mcpp` 公开仓的版本演进。 > 格式参考 [Keep a Changelog](https://keepachangelog.com/zh-CN/1.1.0/)。 +## [2026.8.1.1] — 2026-08-01 + +### 修复 + +- **`mcpp` 的进度输出在非 TTY 下不再被 libc 缓冲区吞掉。** 全部状态行此前都是裸 `std::println` 且**无一处 flush**,仓库里也没有 `setvbuf` —— 于是「什么时候能看见」完全由各平台 libc 的缓冲区大小决定,而这个数字三个平台都不一样:musl(Linux 发行版的链接方式)写死 `BUFSIZ = 1024` 且忽略 `st_blksize`,Apple libc 取 `st_blksize`(管道上是 65536),MSVCRT 用 4096 且**不支持行缓冲**。 + + 实测同一个 97 成员工作空间的同一段 ~13 KB 状态输出:Linux 冲了 13 次,macOS **0 次**。macOS 的 CI 日志因此只有测试二进制自己的输出(它们是独立进程,各自退出时 flush),mcpp 自己的**一行都没有**;等这一步被 job timeout 杀掉时,整个缓冲区连同那 13 KB 一起没了 —— 一个 45 分钟、零可归因输出的步骤。 + + 现在 `main()` 把 stdout 设为行缓冲,`mcpp::ui` 的每个写 stdout 的函数额外显式 flush(Windows 上 MSVCRT 会把 `_IOLBF` 当 `_IOFBF`,所以两条腿都要有)。实测:同一条命令从 3 次块写变成 391 次逐行写。 + +- **`mcpp test` 的 `finished in` 不再漏算构建时间。** 计时起点此前在包级构建与批量测试构建**之后**,只覆盖逐测试循环。实测一个成员打印 `finished in 6.53s`,真实墙钟 **93.5s** —— 14 倍的低报,而且**恰好在构建最重、最需要这个数字的成员上最不准**。现在起点移到 Phase A 之前,并拆成 `finished in 93.5s (build 87.0s + run 6.5s)`:测试只要几毫秒、链接要 90 秒的成员,在合并数字里和「测试套件很慢」长得一样,拆开才分得出。 + +- **`--message-format json` 的 stdout 不再被非 JSON 行污染,且污染是不对称的。** 静音标志此前由 `run_tests` 自己设置,而 `--workspace` 的 `Workspace testing member` 表头由扇出层在调用**之前**打 —— 第一个成员的表头漏进 NDJSON 流,第二个起被静音。现在扇出层在第一个成员之前就静音。 + +### 新增 + +- **`mcpp test` 默认有界。** `--timeout` 的默认值从 `0`(不限)改为 **300 秒**;`--timeout 0` 仍然表示不限,只是现在要显式要求。无人值守的 CI 不该被一个挂住的测试吃掉整个 job,而「不限」作为默认值恰恰保证了它可以。 + +- **`--build-timeout`(默认关闭)—— `--timeout` 覆盖不到的另一半。** 此前 `--timeout` 只包住测试**进程的运行**,而 `mcpp test` 的三次 ninja 驱动(包级构建、批量测试构建、逐测试构建)**全都没有期限**。实测一个 macOS lane 卡在某成员的 14 次可执行链接上超过 44 分钟,`--timeout` 设多大都无效。现在每次驱动各自独立计时,超时报成该成员的构建失败并继续下一个成员,失败行明确写「build timeout」而非笼统的 compile 失败。 + + **它与 `--timeout` 不同,默认不开,这个不对称是实测出来的而非风格选择**:单个测试跑过 5 分钟不寻常,而冷依赖构建跑过 15 分钟很平常 —— mcpp-index 有一个成员要从源码建 OpenCV,实测 linux 1019s、windows 1289s。给它一个默认上限会把「慢但正确」的构建判红并让人以为是 mcpp 的错。构建可以跑多久是工程自身的性质,所以由工程来说;mcpp 只需要让「说得出来」成为可能 —— 而这正是原先缺的东西。 + + 平台限制如实说明:deadline 执行器在 Windows 上没有 kill-by-handle 路径,该值被忽略(POSIX only)。 + +- **`--workspace-timeout`(默认 0 = 不限)。** 扇出是串行的,一个没有上界的成员会拖住它后面的所有成员。超时后停止扇出、**如实汇总已跑完的成员并列出未运行的**,而不是把进程留给 CI 去 kill(那会把它想说的话一并丢掉)。 + +- **`mcpp test --workspace` 有了进度与计时。** 逐成员 `M/N` 进度、逐测试耗时(`t1 ... ok (0.31s)`)、逐成员耗时,以及 workspace 级汇总 + `slowest:` 榜: + + ``` + workspace result ok. 97 member(s); 412 passed; 0 failed; finished in 355.20s + slowest: libs/jsc 93.5s, libs/install 32.2s, libs/http 24.1s + ``` + + 此前扇出只打 `all N member(s) passed` —— 定位「哪个成员吃掉了墙钟」只能靠反解 CI 日志时间戳。 + +- **JSON 记录带成员限定。** 每条 test 记录新增 `"member"`,`summary` 新增 `"member"` / `"build_ms"` / `"run_ms"`,流末尾新增一条 `workspace_summary`(含 `failed_members` / `not_run`)。一旦两个成员都有名为 `smoke` 的测试,裸测试名就不再可归因。 + +- **macOS 上不注入运行期库路径这件事,现在会说出来。** `runtime_library_path_key()` 在 macOS 返回空串(理由正确:`DYLD_LIBRARY_PATH` 会波及 ninja 启动的每个可执行文件,可能让系统框架加载到私有 libc++)。后果是依赖 `[runtime] library_dirs` 的测试在 Linux/Windows 通过、在 macOS 以 dyld 错误失败,而这条差异此前**零诊断**。现在当计划里确有 `runtimeLibraryDirs` 时给一条点名平台与 rpath 兜底的警告。 + +分析与实施计划见 `.agents/docs/2026-07-31-test-workspace-observability-analysis.md` 与 `.agents/docs/2026-07-31-test-observability-implementation-plan.md`。 + ## [2026.7.31.1] — 2026-07-31 ### 新增 diff --git a/docs/00-getting-started.md b/docs/00-getting-started.md index ca57b56f..d53f958d 100644 --- a/docs/00-getting-started.md +++ b/docs/00-getting-started.md @@ -86,9 +86,25 @@ mcpp test # compile and run tests/**/*.cpp — one binary per file # framework-agnostic (bare main, or gtest via [dev-dependencies]) mcpp test # only tests whose name contains mcpp test --list # enumerate tests without building -mcpp test --timeout 30 # kill a test still running after 30s +mcpp test --timeout 30 # kill a test still RUNNING after 30s (default 300; 0 = no limit) +mcpp test --build-timeout 120 # kill a compile/link still running after 120s (off by default) ``` +The *run* half is bounded by default so an unattended CI job cannot be consumed by +a single hung test. The two deadlines cover different halves and neither implies +the other: `--timeout` bounds the test *process*, `--build-timeout` bounds one +ninja drive (the package build, the bulk test build, and each per-test build are +timed separately). **A link that never returns is a `--build-timeout` case; no +`--timeout` value stops it.** + +`--build-timeout` is off by default, and the asymmetry is measured rather than +stylistic: a test binary running over five minutes is unusual, a cold dependency +build running over fifteen is ordinary (one mcpp-index member builds OpenCV from +source in 1019s on Linux and 1289s on Windows). A default ceiling would turn +slow-but-correct builds red. How long a build may take is a property of the +project, so the project says it. POSIX-only — the deadline runner has no +kill-by-handle path on Windows, where the value is ignored. + ## Adding Dependencies Declare dependencies in `mcpp.toml`: diff --git a/docs/06-workspace.md b/docs/06-workspace.md index 8de2da7e..79813468 100644 --- a/docs/06-workspace.md +++ b/docs/06-workspace.md @@ -195,6 +195,42 @@ member. `mcpp test --workspace` reports each member separately and continues pas failing member, exiting non-zero if any member failed — ideal as a single, shell-free CI step for a workspace that tests many libraries. +#### What the fan-out reports + +``` + Workspace testing member 'libs/core' (3/97) +test_paths ... ok (0.31s) + test result ok. 7 passed; 0 failed; finished in 9.50s (build 8.90s + run 0.60s) + Workspace member 'libs/core' (3/97) ok — 7 passed in 9.50s +... + workspace result ok. 97 member(s); 412 passed; 0 failed; finished in 355.20s + slowest: libs/jsc 93.5s, libs/install 32.2s, libs/http 24.1s +``` + +`M/N` progress, per-test durations, and a per-member time split into **build** vs +**run**. The split is the useful part: a member whose tests take milliseconds but +whose link takes 90 seconds looks identical to a slow test suite in a single merged +number, and only one of those is worth investigating. + +`--message-format json` carries the same data as NDJSON. Every test record is +member-qualified (`"member"`), and the stream ends with a `workspace_summary` +record naming the failed and not-run members — a bare test name is ambiguous the +moment two members both have a `smoke`. + +#### Bounding the fan-out + +```bash +mcpp test --workspace --timeout 60 # per-test RUN deadline (default 300) +mcpp test --workspace --build-timeout 300 # per-ninja-drive deadline (default 0 = no limit) +mcpp test --workspace --workspace-timeout 1800 # whole fan-out (default 0 = no limit) +``` + +The fan-out is serial, so an unbounded member stalls every member after it. All +three deadlines report rather than abort: a timed-out test fails that test and the +fan-out continues; a timed-out build fails that member; `--workspace-timeout` stops +the fan-out and lists what did not run instead of leaving the CI job to kill the +process (which discards everything it had to say). + ## 6. Directory Layout The recommended directory layout for a workspace: diff --git a/docs/zh/00-getting-started.md b/docs/zh/00-getting-started.md index 37895184..79ea22da 100644 --- a/docs/zh/00-getting-started.md +++ b/docs/zh/00-getting-started.md @@ -87,9 +87,21 @@ mcpp test # 编译并运行 tests/**/*.cpp —— 每文件一个 # 框架无关(裸 main,或经 [dev-dependencies] 使用 gtest) mcpp test # 只运行名字包含 的测试 mcpp test --list # 只枚举测试,不构建 -mcpp test --timeout 30 # 运行超过 30s 的测试将被终止并计为失败 +mcpp test --timeout 30 # 单个测试**运行**超过 30s 被终止(默认 300;0 = 不限) +mcpp test --build-timeout 120 # 单次编译/链接超过 120s 被终止(默认关闭) ``` +**运行**那一半默认有界 —— 无人值守的 CI 不该被一个挂住的测试吃掉整个 job。两个期限 +覆盖的是不同的一半,互不蕴含:`--timeout` 约束测试**进程的运行**,`--build-timeout` +约束**单次 ninja 驱动**(包级构建、批量测试构建、每个测试各自独立计时)。 +**链接卡死属于 `--build-timeout`,`--timeout` 设多大都无效。** + +`--build-timeout` 默认关闭,这个不对称是**实测**出来的而非风格选择:单个测试跑过 5 分钟 +不寻常,而冷依赖构建跑过 15 分钟很平常(mcpp-index 有一个成员要从源码建 OpenCV, +linux 1019s、windows 1289s)。给它一个默认上限会把「慢但正确」的构建判红。构建可以跑多久 +是工程自身的性质,所以由工程来说。仅 POSIX 有效 —— Windows 上没有 kill-by-handle 路径, +该值被忽略。 + ## 添加依赖 在 `mcpp.toml` 中声明依赖: diff --git a/docs/zh/06-workspace.md b/docs/zh/06-workspace.md index 9c79cc84..695b917f 100644 --- a/docs/zh/06-workspace.md +++ b/docs/zh/06-workspace.md @@ -192,6 +192,38 @@ mcpp run -p server -- --port 8080 `mcpp test --workspace` 逐成员独立汇报、遇失败继续,只要有任一成员失败即非零退出—— 非常适合作为「一个测试众多库的工作空间」的单条、无 shell 的 CI 步骤。 +#### 扇出汇报什么 + +``` + Workspace testing member 'libs/core' (3/97) +test_paths ... ok (0.31s) + test result ok. 7 passed; 0 failed; finished in 9.50s (build 8.90s + run 0.60s) + Workspace member 'libs/core' (3/97) ok — 7 passed in 9.50s +... + workspace result ok. 97 member(s); 412 passed; 0 failed; finished in 355.20s + slowest: libs/jsc 93.5s, libs/install 32.2s, libs/http 24.1s +``` + +`M/N` 进度、逐测试耗时,以及**按 build / run 拆开**的成员耗时。拆开才是有用的那部分: +一个测试只要几毫秒、但链接要 90 秒的成员,在单个合并数字里和「测试套件很慢」长得一模一样, +而两者里只有一个值得去查。 + +`--message-format json` 承载同样的数据。每条 test 记录都带 `"member"` 限定,流末尾是一条 +`workspace_summary`,列出失败成员与未运行成员 —— 一旦两个成员都有名为 `smoke` 的测试, +裸测试名就不再可归因。 + +#### 给扇出设期限 + +```bash +mcpp test --workspace --timeout 60 # 单测试**运行**期限(默认 300) +mcpp test --workspace --build-timeout 300 # 单次 ninja 驱动期限(默认 0 = 不限) +mcpp test --workspace --workspace-timeout 1800 # 整条扇出(默认 0 = 不限) +``` + +扇出是串行的,所以一个没有上界的成员会拖住它后面的所有成员。三个期限都是**汇报而非中止**: +测试超时只判该测试失败、扇出继续;构建超时只判该成员失败;`--workspace-timeout` 停止扇出并 +列出未运行的成员 —— 而不是把进程留给 CI 去 kill(那会把它想说的话一并丢掉)。 + ## 6. 目录布局 工作空间推荐的目录布局: diff --git a/mcpp.toml b/mcpp.toml index 6177f431..685d5c4e 100644 --- a/mcpp.toml +++ b/mcpp.toml @@ -1,6 +1,6 @@ [package] name = "mcpp" -version = "2026.7.31.1" +version = "2026.8.1.1" description = "Modern C++ build & package management tool" license = "Apache-2.0" authors = ["mcpp-community"] diff --git a/src/build/backend.cppm b/src/build/backend.cppm index 63a49317..66679acc 100644 --- a/src/build/backend.cppm +++ b/src/build/backend.cppm @@ -19,6 +19,17 @@ struct BuildOptions { // Keep building unaffected goals after a failure (ninja -k 0). Used by // `mcpp test` to pre-build all test goals in one parallel pass. bool keepGoing = false; + // Wall-clock ceiling for THIS ninja invocation, in seconds. 0 = no limit. + // + // `mcpp test --timeout` only ever bounded the test binary's *run*; the + // three build drives around it had no deadline at all, so a build that + // never finishes (measured: 14 executables linking against a prebuilt + // JavaScriptCore on macOS, >44 min and still going) could only be stopped + // by the CI job timeout — which kills the process and takes its unflushed + // output with it. This is the knob that turns that into an attributable + // failure. POSIX only: the deadline runner has no kill-by-handle path on + // Windows (see mcpp.platform.process), where the value is ignored. + unsigned buildTimeoutSecs = 0; }; struct BuildResult { @@ -36,6 +47,11 @@ struct BuildError { std::string message; std::optional where; std::string diagnosticOutput; + // Set when the drive was killed by buildTimeoutSecs rather than failing to + // compile. A flag, not a message prefix: `mcpp test` reports a timed-out + // compile differently from a broken one, and matching on prose is how that + // distinction silently rots. + bool timedOut = false; }; struct Backend { diff --git a/src/build/execute.cppm b/src/build/execute.cppm index dacbcc69..bb0be796 100644 --- a/src/build/execute.cppm +++ b/src/build/execute.cppm @@ -798,7 +798,36 @@ export struct TestOptions { std::string filter; // substring match on the path-based test name; empty = all TestMessageFormat format = TestMessageFormat::Human; bool list = false; // enumerate only, no build/run - int timeoutSecs = 0; // per-test run deadline; 0 = unlimited + // Per-test RUN deadline. The default is deliberately non-zero: `mcpp test` + // is something CI runs unattended, and an unbounded default makes a single + // hung test able to consume the whole job with nothing to show for it. + // `--timeout 0` still means "no limit", it just has to be asked for. + int timeoutSecs = 300; + // Per-ninja-invocation deadline (Phase A, the bulk pass, and each per-test + // drive are timed separately). Covers the half `--timeout` never could: + // a compile or link that never returns. POSIX only — see BuildOptions. + // + // Unlike timeoutSecs this defaults to OFF, and the asymmetry is measured, + // not stylistic. A single test binary running longer than five minutes is + // unusual; a cold dependency build taking longer than fifteen is ordinary — + // one mcpp-index member (OpenCV from source) measures 1019s on Linux and + // 1289s on Windows. A default ceiling would turn those slow-but-correct + // builds red and blame mcpp for it. "How long may a build take" is a + // property of the project, so the project says it; mcpp only has to make + // saying it possible, which is what was missing. + int buildTimeoutSecs = 0; +}; + +// What one member's `run_tests` actually did. `--workspace` fans out over +// members and needs this to report per-member progress and a workspace total; +// the exit code alone cannot say how many tests ran or where the time went. +export struct TestRunSummary { + int passed = 0; + int failed = 0; + long long buildMs = 0; // Phase A + bulk pass + per-test drives + long long runMs = 0; // the test binaries' own execution + long long elapsedMs = 0; // wall clock for the whole member + bool packageError = false; // Phase A failed: no test ever ran }; // Minimal JSON string escaping for the --message-format json records. Same @@ -827,8 +856,28 @@ static std::string test_json_escape(std::string_view s) { // with dev-deps, run each test binary, summarize. export int run_tests(std::span passthrough, BuildOverrides overrides = {}, - TestOptions testOpts = {}) { + TestOptions testOpts = {}, + TestRunSummary* summaryOut = nullptr) { const bool json = (testOpts.format == TestMessageFormat::Json); + // The member this call is scoped to (empty outside a workspace). Threaded + // into every JSON record so a `--workspace` stream can be attributed: a + // bare test name is ambiguous the moment two members both have a `smoke`. + const std::string memberName = overrides.package_filter; + TestRunSummary summary; + struct SummaryWriter { + TestRunSummary* out; const TestRunSummary* src; + ~SummaryWriter() { if (out) *out = *src; } + } summaryWriter{summaryOut, &summary}; + // Wall clock for the WHOLE member, started before Phase A. The old `t0` + // sat after Phase A and the bulk pass, so `finished in` reported only the + // per-test loop: measured on one member, 6.53s printed against 93.5s + // actual — a 14x understatement, and worst exactly on the build-heavy + // members where the number matters. + auto tMember = std::chrono::steady_clock::now(); + auto member_ms = [&tMember] { + return std::chrono::duration_cast( + std::chrono::steady_clock::now() - tMember).count(); + }; // JSON mode: stdout carries NDJSON only. All ui::status/info lines print // to stdout, so silence them wholesale; errors already go to stderr. if (json) mcpp::ui::set_quiet(true); @@ -917,7 +966,8 @@ export int run_tests(std::span passthrough, auto abs = std::filesystem::absolute(testRoot / t.main) .lexically_normal().generic_string(); if (json) - std::println("{{\"test\":\"{}\",\"main\":\"{}\"}}", + std::println("{{\"member\":\"{}\",\"test\":\"{}\",\"main\":\"{}\"}}", + test_json_escape(memberName), test_json_escape(t.name), test_json_escape(abs)); else std::println("{}", t.name); @@ -1022,9 +1072,11 @@ export int run_tests(std::span passthrough, : "run_fail"; std::string signal = (r.exitCode > 128 && r.exitCode < 128 + 65) ? std::to_string(r.exitCode - 128) : "null"; - std::println("{{\"test\":\"{}\",\"status\":\"{}\",\"exit_code\":{},\"signal\":{}," + std::println("{{\"member\":\"{}\",\"test\":\"{}\",\"status\":\"{}\"," + "\"exit_code\":{},\"signal\":{}," "\"duration_ms\":{},\"timed_out\":{}," "\"compile_output\":\"{}\",\"run_output\":\"{}\"}}", + test_json_escape(memberName), test_json_escape(r.name), st, r.exitCode, signal, r.durationMs, r.timedOut ? "true" : "false", test_json_escape(r.compileOutput), test_json_escape(r.runOutput)); @@ -1053,8 +1105,14 @@ export int run_tests(std::span passthrough, if (!pkgTargets.empty()) { mcpp::build::BuildOptions aOpts; aOpts.ninjaTargets = pkgTargets; + aOpts.buildTimeoutSecs = static_cast(testOpts.buildTimeoutSecs); + auto tPhaseA = std::chrono::steady_clock::now(); auto a = backend->build(ctx->plan, aOpts); + summary.buildMs += std::chrono::duration_cast( + std::chrono::steady_clock::now() - tPhaseA).count(); if (!a) { + summary.packageError = true; + summary.elapsedMs = member_ms(); std::fflush(stdout); if (json) std::println("{{\"error\":\"package\",\"compile_output\":\"{}\"}}", @@ -1096,20 +1154,40 @@ export int run_tests(std::span passthrough, { mcpp::build::BuildOptions bulk; bulk.keepGoing = true; + bulk.buildTimeoutSecs = static_cast(testOpts.buildTimeoutSecs); for (auto& lu : ctx->plan.linkUnits) if (filter_match(lu)) bulk.ninjaTargets.push_back(lu.output.generic_string()); - if (!bulk.ninjaTargets.empty()) + if (!bulk.ninjaTargets.empty()) { + auto tBulk = std::chrono::steady_clock::now(); (void)backend->build(ctx->plan, bulk); + summary.buildMs += std::chrono::duration_cast( + std::chrono::steady_clock::now() - tBulk).count(); + } } // Then build + run each test in sequence; collect results. - auto t0 = std::chrono::steady_clock::now(); auto runtimeEnvKey = mcpp::platform::env::runtime_library_path_key(); auto runtimeEnvValue = mcpp::platform::env::prepend_path_list( runtimeEnvKey, ctx->plan.runtimeLibraryDirs); + // macOS deliberately has no runtime-library-path key (env.cppm): injecting + // DYLD_LIBRARY_PATH would reach every executable ninja launches and can + // make system frameworks load a private libc++. The consequence is that a + // test needing `[runtime] library_dirs` passes on Linux/Windows and fails + // here with a dyld error that names neither the cause nor the platform — + // so say it out loud rather than leaving the difference silent. + if constexpr (mcpp::platform::is_macos) { + if (runtimeEnvKey.empty() && !ctx->plan.runtimeLibraryDirs.empty()) { + mcpp::diag::warning("test/runtime-path", + "macOS does not inject a runtime library path for test binaries " + "(DYLD_LIBRARY_PATH is deliberately not set); dependencies must be " + "reachable through the binary's rpath. A dyld 'image not found' " + "failure below is this difference, not a broken test."); + } + } + for (auto& lu : ctx->plan.linkUnits) { if (!filter_match(lu)) continue; @@ -1123,12 +1201,22 @@ export int run_tests(std::span passthrough, mcpp::build::BuildOptions bOpts; bOpts.ninjaTargets = {lu.output.generic_string()}; + bOpts.buildTimeoutSecs = static_cast(testOpts.buildTimeoutSecs); + auto tBuild = std::chrono::steady_clock::now(); auto b = backend->build(ctx->plan, bOpts); + summary.buildMs += std::chrono::duration_cast( + std::chrono::steady_clock::now() - tBuild).count(); if (!b) { if (!json) { // The test's own diagnostics, right under its FAIL line — a // reader fixes one test with one contiguous block of output. - std::println("{} ... FAIL (compile)", lu.targetName); + mcpp::ui::plain(std::format("{} ... FAIL ({}, {:.2f}s)", + lu.targetName, + b.error().timedOut + ? std::format("build timeout after {}s", + testOpts.buildTimeoutSecs) + : std::string{"compile"}, + static_cast(test_ms()) / 1000.0)); std::fflush(stdout); if (!b.error().diagnosticOutput.empty()) { std::fputs(b.error().diagnosticOutput.c_str(), stderr); @@ -1177,6 +1265,7 @@ export int run_tests(std::span passthrough, bool timedOut = false; int exitCode; std::string runOutput; + auto tRun = std::chrono::steady_clock::now(); if (json) { auto rr = mcpp::platform::process::capture_exec_deadline( argv, childEnv, deadline, &timedOut); @@ -1186,25 +1275,29 @@ export int run_tests(std::span passthrough, exitCode = mcpp::platform::process::run_exec_deadline( argv, childEnv, deadline, &timedOut); } + summary.runMs += std::chrono::duration_cast( + std::chrono::steady_clock::now() - tRun).count(); if (timedOut) { - if (!json) std::println("{} ... FAIL (timeout after {}s)", - lu.targetName, testOpts.timeoutSecs); + if (!json) mcpp::ui::plain(std::format("{} ... FAIL (timeout after {}s)", + lu.targetName, testOpts.timeoutSecs)); results.push_back({lu.targetName, TestResult::St::RunFail, exitCode, {}, std::move(runOutput), test_ms(), true}); } else if (exitCode == 0) { - if (!json) std::println("{} ... ok", lu.targetName); + if (!json) mcpp::ui::plain(std::format("{} ... ok ({:.2f}s)", lu.targetName, + static_cast(test_ms()) / 1000.0)); results.push_back({lu.targetName, TestResult::St::Pass, 0, {}, std::move(runOutput), test_ms()}); } else { - if (!json) std::println("{} ... FAIL (exit {})", lu.targetName, exitCode); + if (!json) mcpp::ui::plain(std::format("{} ... FAIL (exit {}, {:.2f}s)", + lu.targetName, exitCode, + static_cast(test_ms()) / 1000.0)); results.push_back({lu.targetName, TestResult::St::RunFail, exitCode, {}, std::move(runOutput), test_ms()}); } emit_json(results.back()); } - auto elapsed = std::chrono::duration_cast( - std::chrono::steady_clock::now() - t0); + summary.elapsedMs = member_ms(); // 7. Summary. int passed = 0; @@ -1215,9 +1308,22 @@ export int run_tests(std::span passthrough, else { ++failed; failures.push_back(r.name); } } + summary.passed = passed; + summary.failed = failed; + + // "build X + run Y" rather than one merged number: on a member whose tests + // are cheap but whose link is not, those two are three orders of magnitude + // apart, and only the split says which one to go look at. + auto timing = std::format("{:.2f}s (build {:.2f}s + run {:.2f}s)", + static_cast(summary.elapsedMs) / 1000.0, + static_cast(summary.buildMs) / 1000.0, + static_cast(summary.runMs) / 1000.0); + if (json) { - std::println("{{\"summary\":{{\"passed\":{},\"failed\":{},\"elapsed_ms\":{}}}}}", - passed, failed, elapsed.count()); + std::println("{{\"summary\":{{\"member\":\"{}\",\"passed\":{},\"failed\":{}," + "\"elapsed_ms\":{},\"build_ms\":{},\"run_ms\":{}}}}}", + test_json_escape(memberName), passed, failed, + summary.elapsedMs, summary.buildMs, summary.runMs); std::fflush(stdout); return failed == 0 ? 0 : 1; } @@ -1225,13 +1331,12 @@ export int run_tests(std::span passthrough, std::println(""); if (failed == 0) { mcpp::ui::status("test result", - std::format("ok. {} passed; 0 failed; finished in {:.2f}s", - passed, static_cast(elapsed.count()) / 1000.0)); + std::format("ok. {} passed; 0 failed; finished in {}", passed, timing)); return 0; } mcpp::ui::error(std::format( - "test result: FAILED. {} passed; {} failed; finished in {:.2f}s", - passed, failed, static_cast(elapsed.count()) / 1000.0)); + "test result: FAILED. {} passed; {} failed; finished in {}", + passed, failed, timing)); std::println(""); std::println("failures:"); for (auto& n : failures) std::println(" {}", n); diff --git a/src/build/ninja_backend.cppm b/src/build/ninja_backend.cppm index fda83ee0..169e3308 100644 --- a/src/build/ninja_backend.cppm +++ b/src/build/ninja_backend.cppm @@ -1395,9 +1395,25 @@ std::expected NinjaBackend::build(const BuildPlan& plan for (auto& ev : plan.toolchain.envOverrides) nenv.emplace_back(ev.key, ev.value); - auto cap = mcpp::platform::process::capture_exec(nargv, nenv); + bool buildTimedOut = false; + auto cap = mcpp::platform::process::capture_exec_deadline( + nargv, nenv, + std::chrono::milliseconds(static_cast(opts.buildTimeoutSecs) * 1000), + &buildTimedOut); std::string out = cap.output; - bool ok = (cap.exit_code == 0); + bool ok = (cap.exit_code == 0) && !buildTimedOut; + + if (buildTimedOut) { + // Report as a build failure with the partial ninja output attached — + // the last edge ninja printed is the one that hung, which is the whole + // point of having a deadline here. + r.exitCode = 1; + r.elapsed = std::chrono::duration_cast( + std::chrono::steady_clock::now() - t0); + return std::unexpected(BuildError{ + std::format("build timed out after {}s", opts.buildTimeoutSecs), + plan.outputDir / "build.ninja", out, /*timedOut=*/true}); + } r.exitCode = ok ? 0 : 1; r.elapsed = std::chrono::duration_cast( diff --git a/src/cli.cppm b/src/cli.cppm index 007a37c3..5e6c6c10 100644 --- a/src/cli.cppm +++ b/src/cli.cppm @@ -54,7 +54,7 @@ void print_usage() { std::println(" mcpp new Create a new package skeleton"); std::println(" mcpp build [options] Build the current package"); std::println(" mcpp run [target] [-- args...] Build + run a binary target"); - std::println(" mcpp test [pattern] [-- args...] Build + run tests/**/*.cpp (--list, --timeout, --message-format json)"); + std::println(" mcpp test [pattern] [-- args...] Build + run tests/**/*.cpp (--list, --timeout, --build-timeout, --message-format json)"); std::println(" mcpp clean [--bmi-cache] Remove target/ (and optionally the build cache)"); std::println(" mcpp add [@] Add a dependency to mcpp.toml"); std::println(" mcpp remove Remove a dependency from mcpp.toml"); @@ -276,7 +276,11 @@ int run(int argc, char** argv) { .option(cl::Option("list") .help("List (filtered) tests without building or running them")) .option(cl::Option("timeout").takes_value().value_name("SECS") - .help("Kill a test still running after SECS seconds (reported as a timeout failure)")) + .help("Kill a test still RUNNING after SECS seconds (default 300; 0 = no limit)")) + .option(cl::Option("build-timeout").takes_value().value_name("SECS") + .help("Kill a compile/link drive still running after SECS seconds (default 0 = no limit; POSIX only)")) + .option(cl::Option("workspace-timeout").takes_value().value_name("SECS") + .help("Stop the --workspace fan-out after SECS seconds and report what did run (default 0 = no limit)")) .option(cl::Option("profile").takes_value().value_name("NAME") .help("Build profile for the test build: release (default) | dev | dist | <[profile.*] name>")) .option(cl::Option("features").takes_value().value_name("LIST") diff --git a/src/cli/cmd_build.cppm b/src/cli/cmd_build.cppm index 715418b7..026deb6e 100644 --- a/src/cli/cmd_build.cppm +++ b/src/cli/cmd_build.cppm @@ -142,15 +142,25 @@ export int cmd_test(const mcpplibs::cmdline::ParsedArgs& parsed, mcpp::build::TestOptions to; if (parsed.positional_count() > 0) to.filter = parsed.positional(0); to.list = parsed.is_flag_set("list"); - if (auto ts = parsed.value("timeout")) { + // The three deadlines share one parser: they differ only in what they + // bound, not in how they are spelled. 0 always means "no limit" — for + // --timeout that now has to be asked for rather than being the default. + int workspaceTimeoutSecs = 0; + auto read_secs = [&parsed](std::string_view flag, int& out) -> bool { + auto ts = parsed.value(std::string{flag}); + if (!ts) return true; int secs = 0; auto [p, ec] = std::from_chars(ts->data(), ts->data() + ts->size(), secs); if (ec != std::errc{} || p != ts->data() + ts->size() || secs < 0) { - mcpp::ui::error(std::format("invalid --timeout '{}' (whole seconds >= 0)", *ts)); - return 2; + mcpp::ui::error(std::format("invalid --{} '{}' (whole seconds >= 0)", flag, *ts)); + return false; } - to.timeoutSecs = secs; - } + out = secs; + return true; + }; + if (!read_secs("timeout", to.timeoutSecs)) return 2; + if (!read_secs("build-timeout", to.buildTimeoutSecs)) return 2; + if (!read_secs("workspace-timeout", workspaceTimeoutSecs)) return 2; if (auto mf = parsed.value("message-format")) { if (*mf == "json") to.format = mcpp::build::TestMessageFormat::Json; else if (*mf != "human") { @@ -164,23 +174,125 @@ export int cmd_test(const mcpplibs::cmdline::ParsedArgs& parsed, // red member never hides the rest. if (auto members = workspace_fanout_members(parsed.is_flag_set("workspace"), ov.package_filter)) { + const bool json = (to.format == mcpp::build::TestMessageFormat::Json); + // Silence the ui BEFORE the first member, not inside run_tests. The + // quiet flag used to be set by run_tests itself, so the fan-out's own + // "testing member" line escaped for member #1 and was suppressed from + // #2 on — one stdout stream, two behaviors, and the stray line broke + // NDJSON for any consumer that parsed it strictly. + if (json) mcpp::ui::set_quiet(true); + int rc = 0; std::vector failed; + std::vector notRun; + std::vector> memberTimes; + int totalPassed = 0, totalFailed = 0; + auto tWs = std::chrono::steady_clock::now(); + auto ws_ms = [&tWs] { + return std::chrono::duration_cast( + std::chrono::steady_clock::now() - tWs).count(); + }; + const long long wsDeadlineMs = + static_cast(workspaceTimeoutSecs) * 1000; + + std::size_t idx = 0; for (auto& mp : *members) { + ++idx; + // Checked BEFORE starting a member rather than after: stopping + // mid-member would leave a half-built member reported as neither + // run nor skipped. + if (wsDeadlineMs > 0 && ws_ms() >= wsDeadlineMs) { + notRun.push_back(mp); + continue; + } mcpp::build::BuildOverrides mo = ov; mo.package_filter = mp; - mcpp::ui::status("Workspace", std::format("testing member '{}'", mp)); - int r = mcpp::build::run_tests(passthrough, mo, to); - if (r != 0) { rc = r; failed.push_back(mp); } - } - if (failed.empty()) mcpp::ui::status("Workspace", - std::format("all {} member(s) passed", members->size())); + std::format("testing member '{}' ({}/{})", mp, idx, members->size())); + mcpp::build::TestRunSummary sum; + int r = mcpp::build::run_tests(passthrough, mo, to, &sum); + totalPassed += sum.passed; + totalFailed += sum.failed; + memberTimes.emplace_back(mp, sum.elapsedMs); + auto secs = static_cast(sum.elapsedMs) / 1000.0; + if (r != 0) { + rc = r; + failed.push_back(mp); + mcpp::ui::status("Workspace", + std::format("member '{}' ({}/{}) FAILED — {} passed, {} failed in {:.2f}s", + mp, idx, members->size(), sum.passed, sum.failed, secs)); + } else { + mcpp::ui::status("Workspace", + std::format("member '{}' ({}/{}) ok — {} passed in {:.2f}s", + mp, idx, members->size(), sum.passed, secs)); + } + } + + auto wsElapsed = ws_ms(); + if (!notRun.empty()) rc = rc ? rc : 1; + + if (json) { + // Member paths are manifest-authored strings, so escape rather + // than assume: one backslash in a member path would otherwise emit + // a stream that is not JSON at all. + auto join = [](const std::vector& v) { + std::string s; + for (auto& x : v) { + if (!s.empty()) s += ','; + s += '"'; + for (char c : x) { + if (c == '"' || c == '\\') s += '\\'; + s += c; + } + s += '"'; + } + return s; + }; + std::println("{{\"workspace_summary\":{{\"members\":{},\"passed\":{},\"failed\":{}," + "\"failed_members\":[{}],\"not_run\":[{}],\"elapsed_ms\":{}}}}}", + members->size(), totalPassed, totalFailed, + join(failed), join(notRun), wsElapsed); + std::fflush(stdout); + return rc; + } + + // Slowest members, printed unconditionally rather than only on failure: + // "which member ate the wall clock" is the question a green-but-slow CI + // run raises, and answering it used to mean reverse-engineering log + // timestamps. + std::ranges::sort(memberTimes, [](auto& a, auto& b) { return a.second > b.second; }); + std::string slowest; + for (std::size_t i = 0; i < memberTimes.size() && i < 3; ++i) { + if (memberTimes[i].second < 1000) break; + if (!slowest.empty()) slowest += ", "; + slowest += std::format("{} {:.1f}s", memberTimes[i].first, + static_cast(memberTimes[i].second) / 1000.0); + } + + auto join_names = [](const std::vector& v) { + std::string s; + for (auto& f : v) { if (!s.empty()) s += ", "; s += f; } + return s; + }; + if (failed.empty() && notRun.empty()) + mcpp::ui::status("workspace result", + std::format("ok. {} member(s); {} passed; 0 failed; finished in {:.2f}s", + members->size(), totalPassed, + static_cast(wsElapsed) / 1000.0)); else - mcpp::ui::error(std::format("workspace test: {}/{} member(s) failed: {}", - failed.size(), members->size(), [&]{ - std::string s; for (auto& f : failed) { if (!s.empty()) s += ", "; s += f; } - return s; }())); + mcpp::ui::error(std::format( + "workspace test: {}/{} member(s) failed; {} passed; {} failed; " + "finished in {:.2f}s", + failed.size(), members->size(), totalPassed, totalFailed, + static_cast(wsElapsed) / 1000.0)); + if (!failed.empty()) + mcpp::ui::plain(std::format(" failed members: {}", join_names(failed))); + if (!notRun.empty()) + mcpp::ui::plain(std::format( + " not run (--workspace-timeout {}s reached): {}", + workspaceTimeoutSecs, join_names(notRun))); + if (!slowest.empty()) + mcpp::ui::plain(std::format(" slowest: {}", slowest)); return rc; } return mcpp::build::run_tests(passthrough, ov, to); diff --git a/src/main.cpp b/src/main.cpp index b249748e..1c2b27ae 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -3,8 +3,28 @@ import std; import mcpp.cli; +import mcpp.ui; int main(int argc, char* argv[]) { + // Line-buffer stdout even when it is not a TTY. + // + // Without this, progress output is block-buffered and the block SIZE is + // whatever the platform's libc picked — which is not the same number + // anywhere: musl (the Linux release linkage) hardcodes BUFSIZ = 1024 and + // ignores st_blksize, Apple libc takes st_blksize, which for a pipe is + // 65536, and MSVCRT uses 4096. Measured on one 97-member workspace: the + // same ~13 KB of status output flushed 13 times on Linux and ZERO times on + // macOS, so the macOS CI log showed only the test binaries' own output (they + // are separate processes and flush at their own exit) and not one line of + // mcpp's. When that run was then killed by the job timeout, the whole buffer + // went with it — a 45-minute step with no attributable output at all. + // + // Lives in mcpp.ui because a non-module TU may not open a global module + // fragment for (Clang rejects `module;` here; GCC accepted it). + // ui::flush() covers the same ground for the ui layer on Windows, where + // MSVCRT silently treats _IOLBF as _IOFBF. + mcpp::ui::set_line_buffered(); + int rc; try { rc = mcpp::cli::run(argc, argv); diff --git a/src/toolchain/fingerprint.cppm b/src/toolchain/fingerprint.cppm index 3c9da298..93890ca1 100644 --- a/src/toolchain/fingerprint.cppm +++ b/src/toolchain/fingerprint.cppm @@ -18,7 +18,7 @@ import mcpp.toolchain.detect; export namespace mcpp::toolchain { -inline constexpr std::string_view MCPP_VERSION = "2026.7.31.1"; +inline constexpr std::string_view MCPP_VERSION = "2026.8.1.1"; struct FingerprintInputs { Toolchain toolchain; diff --git a/src/ui.cppm b/src/ui.cppm index 5229adb8..b61e5e1d 100644 --- a/src/ui.cppm +++ b/src/ui.cppm @@ -71,6 +71,23 @@ void diagnostic(const Diagnostic& d); // Plain output (no verb), respecting -q flag. void plain(std::string_view message); +// Flush stdout. Every stdout-writing function above already calls this, so +// callers only need it when they wrote to stdout directly (std::println) and +// want that line visible now rather than whenever the libc buffer happens to +// fill. main() also sets stdout line-buffered, which covers the POSIX +// platforms; this is what makes the guarantee hold on Windows too, where +// MSVCRT treats _IOLBF as _IOFBF. Progress-driven output must be visible while +// the process is still running: a build that is killed mid-flight is exactly +// when its last lines matter most. +void flush(); + +// Make stdout line-buffered. Call once, before any output. See main() for why +// this is not left to the libc default: the default block size is a different +// number on every platform (musl 1024, Apple libc st_blksize = 65536 on a pipe, +// MSVCRT 4096), so identical output becomes visible at wildly different times — +// and not at all if the process is killed before its buffer fills. +void set_line_buffered(); + // --- progress bar (single-line, \r-rewritten) --- class ProgressBar { public: @@ -225,6 +242,27 @@ bool is_color_enabled() { return g_color; } void set_quiet(bool q) { g_quiet = q; } bool is_quiet() { return g_quiet; } +void flush() { std::fflush(stdout); } + +void set_line_buffered() { +#if defined(_WIN32) + // Not on Windows, and not as a preference. The UCRT documents setvbuf's + // size as `2 <= size <= INT_MAX`, and a zero goes through the + // invalid-parameter handler, whose default action terminates the process: + // 0xC0000409, which git-bash reports as a bare exit 127. The freshly built + // mcpp.exe died on `--version` before printing anything. + // + // Passing a real size instead would buy nothing: MSVCRT has no line + // buffering at all — it accepts _IOLBF and treats it as _IOFBF. Windows + // gets the same guarantee from ui::flush(), which every stdout-writing + // function here calls, so the platform that cannot do this cheaply is also + // the one that does not need it: its 4096-byte block is the smallest of the + // three anyway, and `mcpp test` routes its result lines through ui::plain. +#else + std::setvbuf(stdout, nullptr, _IOLBF, 0); +#endif +} + void status(std::string_view verb, std::string_view message) { if (g_quiet) return; init(); @@ -235,6 +273,7 @@ void status(std::string_view verb, std::string_view message) { } else { std::println("{} {}", v, message); } + flush(); } void info(std::string_view verb, std::string_view message) { @@ -247,6 +286,7 @@ void info(std::string_view verb, std::string_view message) { } else { std::println("{} {}", v, message); } + flush(); } void finished(std::string_view profile, std::chrono::milliseconds elapsed, @@ -269,6 +309,7 @@ void finished(std::string_view profile, std::chrono::milliseconds elapsed, } else { std::println("{} {}", v, msg); } + flush(); } void warning(std::string_view message) { @@ -292,6 +333,7 @@ void error(std::string_view message) { void plain(std::string_view message) { if (g_quiet) return; std::println("{}", message); + flush(); } void diagnostic(const Diagnostic& d) { diff --git a/tests/e2e/153_test_isolation.sh b/tests/e2e/153_test_isolation.sh index 6602c9e8..473d6403 100755 --- a/tests/e2e/153_test_isolation.sh +++ b/tests/e2e/153_test_isolation.sh @@ -31,8 +31,10 @@ code=$? set -e [[ $code -eq 1 ]] || { echo "expected exit 1, got $code: $out"; exit 1; } [[ "$out" == *"ok ... ok"* ]] || { echo "passing test did not run: $out"; exit 1; } -[[ "$out" == *"runfail ... FAIL (exit 1)"* ]] || { echo "runtime failure not reported: $out"; exit 1; } -[[ "$out" == *"nocompile ... FAIL (compile)"* ]] || { echo "compile failure not isolated: $out"; exit 1; } +# Per-test lines now carry the test's own wall time — match the prefix, not the +# whole line, so the duration can be there without pinning its formatting here. +[[ "$out" == *"runfail ... FAIL (exit 1,"* ]] || { echo "runtime failure not reported: $out"; exit 1; } +[[ "$out" == *"nocompile ... FAIL (compile,"* ]] || { echo "compile failure not isolated: $out"; exit 1; } [[ "$out" == *"1 passed"* && "$out" == *"2 failed"* ]] || { echo "bad summary: $out"; exit 1; } # Package-level failure stays a hard error: break a src module, all-red is wrong, @@ -47,5 +49,5 @@ out2=$("$MCPP" test 2>&1) code2=$? set -e [[ $code2 -ne 0 ]] || { echo "package error must fail: $out2"; exit 1; } -[[ "$out2" != *"nocompile ... FAIL (compile)"* ]] || { echo "package error misattributed to tests: $out2"; exit 1; } +[[ "$out2" != *"nocompile ... FAIL (compile,"* ]] || { echo "package error misattributed to tests: $out2"; exit 1; } echo OK diff --git a/tests/e2e/155_test_json.sh b/tests/e2e/155_test_json.sh index 186ba6ff..1da63c15 100755 --- a/tests/e2e/155_test_json.sh +++ b/tests/e2e/155_test_json.sh @@ -40,7 +40,11 @@ echo "$out" | grep -q '"exit_code":1' || { echo "miss echo "$out" | grep -q '"test":"nocompile","status":"compile_fail"' || { echo "missing compile_fail record"; exit 1; } echo "$out" | grep -q 'D2X_YOUR_ANSWER' || { echo "compile_output missing diagnostics"; exit 1; } echo "$out" | grep -q 'hello from ok' || { echo "run_output not captured"; exit 1; } -echo "$out" | grep -q '"summary":{"passed":1,"failed":2' || { echo "missing summary"; exit 1; } +# The summary now leads with the member it belongs to (empty outside a +# workspace) and carries the build/run split, so match the counts, not the +# whole object prefix. +echo "$out" | grep -q '"passed":1,"failed":2' || { echo "missing summary"; exit 1; } +echo "$out" | grep -qE '"build_ms":[0-9]+,"run_ms":[0-9]+' || { echo "summary missing build/run split"; exit 1; } # Invalid format value → usage error set +e diff --git a/tests/e2e/158_test_signal_and_duration.sh b/tests/e2e/158_test_signal_and_duration.sh index 03e24a06..84e88d6f 100755 --- a/tests/e2e/158_test_signal_and_duration.sh +++ b/tests/e2e/158_test_signal_and_duration.sh @@ -37,5 +37,6 @@ echo "$out" | grep -q '"test":"ok","status":"pass"' || { echo "ok test missing"; # 人读输出同样用 shell 惯例退出码 out2=$("$MCPP" test crash 2>&1) || true -[[ "$out2" == *"crash ... FAIL (exit 139)"* ]] || { echo "human output not 139: $out2"; exit 1; } +# Prefix match: the line now also carries the test's wall time. +[[ "$out2" == *"crash ... FAIL (exit 139,"* ]] || { echo "human output not 139: $out2"; exit 1; } echo OK diff --git a/tests/e2e/178_test_observability.sh b/tests/e2e/178_test_observability.sh new file mode 100755 index 00000000..74c29ae4 --- /dev/null +++ b/tests/e2e/178_test_observability.sh @@ -0,0 +1,167 @@ +#!/usr/bin/env bash +# requires: unix-shell +# 178_test_observability.sh — `mcpp test` is streamed, timed and bounded. +# +# Four properties, each of which used to be absent and each of which cost a real +# CI investigation: +# +# 1. stdout is line-buffered even into a pipe. It used to be block-buffered +# with a libc-dependent block SIZE (musl 1 KB, Apple libc 64 KB on a pipe), +# so the same ~13 KB of status output flushed 13 times on Linux and zero +# times on macOS — and when the job timeout then killed the process, the +# whole buffer went with it: a 45-minute step with no attributable output. +# 2. Per-test and per-member timings are printed, split into build vs run. +# The old `finished in` started its clock AFTER the package build, so a +# member that spent 87s linking reported 6.53s. +# 3. `--timeout` bounds a hung test RUN and the fan-out continues past it. +# 4. `--build-timeout` bounds a hung compile/link — the half `--timeout` +# never covered, and the one that actually fires in practice. +# +# The `# requires:` line above must stay on line 2 — run_all.sh reads it with +# `sed -n '2p'`, so a requires buried in this block is silently inert (which is +# how an earlier revision of this file ran on Windows and failed there). +# unix-shell, not gcc: macOS is the platform this whole file exists for, and it +# has no GCC. Windows is excluded on purpose — the deadline runner has no +# kill-by-handle path there (mcpp.platform.process), so --timeout and +# --build-timeout are documented POSIX-only and cannot be asserted. +# +# See .agents/docs/2026-07-31-test-workspace-observability-analysis.md. +set -uo pipefail + +TMP=$(mktemp -d) +trap "rm -rf $TMP" EXIT +cd "$TMP" + +fail() { echo "FAIL: $*"; exit 1; } + +# ── fixture: a fast member and a slow-to-RUN member ─────────────────────── +mkdir -p fast/tests slow/tests +cat > mcpp.toml <<'EOF' +[workspace] +members = ["fast", "slow"] +EOF +for m in fast slow; do + printf '[package]\nname = "%s"\nversion = "0.1.0"\n' "$m" > "$m/mcpp.toml" +done +cat > fast/tests/quick.cpp <<'EOF' +int main() { return 0; } +EOF +cat > slow/tests/hang.cpp <<'EOF' +#include +#include +int main() { std::this_thread::sleep_for(std::chrono::seconds(30)); return 0; } +EOF + +# ── 1. streaming: output arrives while the process is still running ─────── +# The fan-out does `fast` first, then blocks 30s inside `slow`. Reading the +# fast member's result out of a pipe within a few seconds is only possible if +# mcpp flushed it; under block buffering nothing appears until exit. +# `<>` opens the fifo read-write, which never blocks and keeps both a reader and +# a writer alive for the whole test. Opening it read-only (or write-only) blocks +# until the other end appears, which is a deadlock waiting to happen — and a +# test written to make hangs debuggable must not be able to hang the suite. +mkfifo pipe +exec 3<>pipe +"$MCPP" test --workspace --timeout 25 >pipe 2>&1 & +mcpp_pid=$! +streamed="" +while IFS= read -r -t 25 line <&3; do + case "$line" in + *"quick ... ok"*) streamed=yes; break ;; + esac +done +kill "$mcpp_pid" 2>/dev/null +wait "$mcpp_pid" 2>/dev/null +exec 3>&- +[ -n "$streamed" ] || fail "no output reached the pipe before the process ended (stdout not flushed)" +echo " ok: stdout streams line-by-line into a pipe" + +# ── 2. timings: per-test duration + build/run split + per-member progress ─ +out=$("$MCPP" test -p fast 2>&1) || fail "test -p fast errored: $out" +echo "$out" | grep -qE "quick \.\.\. ok \([0-9]+\.[0-9]+s\)" \ + || { echo "$out"; fail "per-test line carries no duration"; } +echo "$out" | grep -qE "finished in [0-9]+\.[0-9]+s \(build [0-9]+\.[0-9]+s \+ run [0-9]+\.[0-9]+s\)" \ + || { echo "$out"; fail "summary carries no build/run split"; } +echo " ok: per-test duration + build/run split" + +# ── 3. --timeout bounds a hung RUN, and the fan-out continues ───────────── +out=$("$MCPP" test --workspace --timeout 2 2>&1) +rc=$? +echo "$out" | grep -q "hang ... FAIL (timeout after 2s)" \ + || { echo "$out"; fail "hung test was not killed by --timeout"; } +echo "$out" | grep -qE "member 'fast' \(1/2\) ok" \ + || { echo "$out"; fail "no per-member progress line"; } +echo "$out" | grep -q "failed members: slow" \ + || { echo "$out"; fail "workspace summary does not name the failed member"; } +[ "$rc" -ne 0 ] || fail "workspace test returned 0 despite a failed member" +echo " ok: --timeout bounds a hung run; fan-out continues; member attributed" + +# `--timeout 0` still means "no limit" — it just has to be asked for now. +"$MCPP" test -p fast --timeout 0 >/dev/null 2>&1 || fail "--timeout 0 rejected" + +# ── 4. --build-timeout bounds a hung COMPILE ───────────────────────────── +# 20k distinct class templates at the default (optimized) profile: seconds to +# compile everywhere, so a 1s ceiling fires with a wide margin. The assertion is +# on the *reported reason*, which must name the build timeout rather than being +# folded into a generic compile failure. +mkdir -p heavy/tests +printf '[package]\nname = "heavy"\nversion = "0.1.0"\n' > heavy/mcpp.toml +{ + i=0 + while [ "$i" -lt 20000 ]; do + printf 'template struct S%d { static constexpr long v = A*%d+1; };\n' "$i" "$i" + printf 'long f%d(long x) { return x + S%d<%d>::v; }\n' "$i" "$i" "$((i % 97))" + i=$((i + 1)) + done + echo 'int main() { return 0; }' +} > heavy/tests/slowbuild.cpp + +out=$(cd heavy && "$MCPP" test --build-timeout 1 2>&1) +echo "$out" | grep -q "build timeout after 1s" \ + || { echo "$out" | head -20; fail "--build-timeout did not stop the slow compile"; } +echo " ok: --build-timeout bounds a slow compile and names itself" + +# Argument validation is shared by all three deadlines. +out=$("$MCPP" test -p fast --build-timeout abc 2>&1) +echo "$out" | grep -q "invalid --build-timeout" || fail "bad --build-timeout accepted" + +# ── 5. --workspace-timeout stops the fan-out and reports what did not run ─ +# Its own fixture, with the slow member FIRST: the deadline is checked before +# each member starts, so it can only skip anything if time has already been +# spent. (In the main fixture `fast` runs first and finishes in milliseconds.) +mkdir -p wst/one/tests wst/two/tests +cat > wst/mcpp.toml <<'EOF' +[workspace] +members = ["one", "two"] +EOF +for m in one two; do + printf '[package]\nname = "wst_%s"\nversion = "0.1.0"\n' "$m" > "wst/$m/mcpp.toml" +done +cp slow/tests/hang.cpp wst/one/tests/hang.cpp +cp fast/tests/quick.cpp wst/two/tests/quick.cpp + +out=$(cd wst && "$MCPP" test --workspace --timeout 3 --workspace-timeout 1 2>&1) +rc=$? +echo "$out" | grep -q "member 'two'" \ + && { echo "$out"; fail "--workspace-timeout did not stop the fan-out"; } +echo "$out" | grep -q "not run (--workspace-timeout 1s reached)" \ + || { echo "$out"; fail "--workspace-timeout did not report skipped members"; } +[ "$rc" -ne 0 ] || fail "workspace timeout returned 0" +echo " ok: --workspace-timeout stops the fan-out and names what did not run" + +# ── 6. JSON contract: no stray lines, member-qualified, workspace summary ─ +out=$("$MCPP" test --workspace --timeout 2 --message-format json 2>/dev/null) +first=$(printf '%s\n' "$out" | head -1) +case "$first" in + '{'*) ;; + *) echo "$out" | head -3; fail "first NDJSON line is not JSON (stdout polluted)" ;; +esac +printf '%s\n' "$out" | grep -q '"member":"fast"' \ + || { echo "$out"; fail "test records are not member-qualified"; } +printf '%s\n' "$out" | grep -q '"workspace_summary"' \ + || { echo "$out"; fail "no workspace_summary record"; } +printf '%s\n' "$out" | grep -q '"failed_members":\["slow"\]' \ + || { echo "$out"; fail "workspace_summary does not name the failed member"; } +echo " ok: JSON stream is clean, member-qualified and has a workspace summary" + +echo "PASS: 178_test_observability" diff --git a/tests/e2e/90_workspace_test.sh b/tests/e2e/90_workspace_test.sh index e4329ebc..650b5ed8 100755 --- a/tests/e2e/90_workspace_test.sh +++ b/tests/e2e/90_workspace_test.sh @@ -64,7 +64,13 @@ set +e out=$("$MCPP" test --workspace 2>&1); rc=$? set -e [ "$rc" -ne 0 ] || { echo "$out"; echo "FAIL: failing member did not fail the run"; exit 1; } -echo "$out" | grep -qi "member(s) failed: libb" || { echo "$out"; echo "FAIL: no per-member failure summary"; exit 1; } +# The failure summary now carries counts and wall time as well as the names, so +# the names moved to their own line (`failed members: libb`) instead of being +# appended to the header. Assert both halves — the counts are what tell a reader +# whether "1 member failed" meant one test or four hundred. +echo "$out" | grep -qiE "workspace test: 1/2 member\(s\) failed" \ + || { echo "$out"; echo "FAIL: no workspace failure header"; exit 1; } +echo "$out" | grep -qi "failed members: libb" || { echo "$out"; echo "FAIL: no per-member failure summary"; exit 1; } echo "$out" | grep -qi "testing member 'liba'" || { echo "FAIL: did not continue past failure"; exit 1; } echo "OK" diff --git a/tests/unit/test_test_options.cpp b/tests/unit/test_test_options.cpp new file mode 100644 index 00000000..a87ee31f --- /dev/null +++ b/tests/unit/test_test_options.cpp @@ -0,0 +1,70 @@ +#include + +import std; +import mcpp.build.backend; +import mcpp.build.execute; + +using namespace mcpp::build; + +// `mcpp test` has to be BOUNDABLE, and its run half bounded by default. It was +// neither: the per-test deadline defaulted to 0 (no limit) and no deadline +// existed for the build drives at all, so a single hung test or link could +// consume an entire unattended CI job with nothing to show for it. These +// defaults are the contract; asserting them here means neither half can drift +// back by an unnoticed edit. +TEST(TestOptions, RunIsBoundedByDefault) { + TestOptions to; + EXPECT_GT(to.timeoutSecs, 0) << "per-test run deadline must default to a limit"; + EXPECT_EQ(to.timeoutSecs, 300); +} + +// The build deadline deliberately does NOT default on, and the asymmetry is +// measured: a test binary running over five minutes is unusual, a cold +// dependency build running over fifteen is ordinary (one mcpp-index member +// builds OpenCV from source in 1019s on Linux, 1289s on Windows). A default +// ceiling would turn slow-but-correct builds red and blame mcpp for it. +TEST(TestOptions, BuildDeadlineIsOptIn) { + TestOptions to; + EXPECT_EQ(to.buildTimeoutSecs, 0) << "a default build ceiling would fail legitimate cold builds"; +} + +// 0 is still reachable — "no limit" did not disappear, it just has to be asked +// for rather than being what you get by not thinking about it. +TEST(TestOptions, ZeroStillMeansUnlimited) { + TestOptions to; + to.timeoutSecs = 0; + to.buildTimeoutSecs = 0; + EXPECT_EQ(to.timeoutSecs, 0); + EXPECT_EQ(to.buildTimeoutSecs, 0); +} + +// A build drive with no explicit ceiling must stay unbounded: BuildOptions is +// shared with `mcpp build`, which is interactive and must not acquire a +// surprise deadline just because `mcpp test` grew one. +TEST(BuildOptions, BuildTimeoutDefaultsToUnbounded) { + BuildOptions bo; + EXPECT_EQ(bo.buildTimeoutSecs, 0u); +} + +// The timeout verdict travels as a flag, not as a message prefix: run_tests +// reports a timed-out compile differently from a broken one, and matching on +// prose is exactly how that distinction rots silently. +TEST(BuildError, TimedOutIsAFlagAndDefaultsFalse) { + BuildError e{"build failed", std::nullopt, "", false}; + EXPECT_FALSE(e.timedOut); + BuildError t{"build timed out after 900s", std::nullopt, "", true}; + EXPECT_TRUE(t.timedOut); +} + +// The fan-out needs more than an exit code to report per-member progress: how +// many tests ran, and where the time went. A zero-initialised summary must be +// safe to print (the "no tests found" early return leaves it untouched). +TEST(TestRunSummary, DefaultsAreZeroAndPrintable) { + TestRunSummary s; + EXPECT_EQ(s.passed, 0); + EXPECT_EQ(s.failed, 0); + EXPECT_EQ(s.buildMs, 0); + EXPECT_EQ(s.runMs, 0); + EXPECT_EQ(s.elapsedMs, 0); + EXPECT_FALSE(s.packageError); +}