Skip to content

Commit 5c60221

Browse files
committed
perf(test): 并行跑测试 + 全绿时不再逐个复驱动 —— 热跑 5.3s → 2.15s
接着上一条(189.7s → 5.3s)。剩下的 5.3s 是 build 3.35s + run 1.84s,两边各修一处。 **1. 全绿时不必逐个复驱动后端(3.35s → 1.85s)** Phase B 先做一次 `-k 0` 的批量构建,然后每个测试再单独驱动一次后端 —— 注释说 "成功的是缓存命中,近似 no-op"。修完 rule E 之后它确实"近似"了,但仍是每次 ~39ms (重发 build.ninja、重写 compile_commands.json、spawn ninja、复核运行期闭包), 83 次就是 3.2s,而且问的是批量构建刚刚已经一次性回答过的问题。 `-k 0` 的退出码当且仅当所有目标都构建成功时为 0 —— 正是那个循环在重新推导的信息。 于是:批量成功 ⇒ 跳过复驱动;批量失败 ⇒ 循环照旧,每个失败仍然归属到自己的测试。 按"故意编坏一个测试"验证过:只有它 FAIL,诊断就在它那一行下面。 **2. 并行跑测试(1.84s → 0.08s)** 原来没有并行执行能力 —— 这是用户问的那一点。但要先说清楚:**它从来不是慢的原因**, 83 个测试的运行阶段总共只有 1.8s / 190s。修完构建侧之后它才变成剩余时间的一半, 这时候才值得做。 - 多于一个测试时**捕获**输出,测试结束时整块打印。直接流式输出 N 个测试会逐行交错, 那不只是难看 —— 失败的断言会变得无法归属,而归属正是这个循环存在的理由。 - **只有一个测试时保持前台流式**。那是调试场景:一个长测试的实时进度比省下的 ~0ms 更值钱,而捕获会把输出一直压到测试结束 —— 包括它挂住的时候,恰恰是最需要 看到输出的时候。 - 汇总时间取**整个阶段的墙钟**而不是各测试耗时之和:并发下后者会超过命令总时长。 并发度走 `resolve_jobs`(`--jobs` / `[build] jobs` / 机器),和构建同一个答案。 热跑 3 次:2.14 / 2.17 / 2.15s。合计 **189.74s → 2.15s(88×)**。 e2e 15/16/17/152/153/154/155/158/159/160/178 全过。
1 parent 4882151 commit 5c60221

1 file changed

Lines changed: 144 additions & 50 deletions

File tree

src/build/execute.cppm

Lines changed: 144 additions & 50 deletions
Original file line numberDiff line numberDiff line change
@@ -30,6 +30,7 @@ import mcpp.platform.runtime_binding;
3030
import mcpp.log;
3131
import mcpp.platform;
3232
import mcpp.platform.capacity;
33+
import mcpp.build.schedule.policy; // resolve_jobs — one answer to "how many at once"
3334
import mcpp.fetcher.progress;
3435
import mcpp.project;
3536
import mcpp.ui;
@@ -1331,9 +1332,21 @@ export int run_tests(std::span<const std::string> passthrough,
13311332
// 6. Phase B. First a single keep-going bulk build over every selected
13321333
// test goal — ninja parallelizes across tests and a failing test does
13331334
// not stop the rest (-k 0). The result is deliberately ignored: the
1334-
// per-test loop below re-drives each goal, where successes are cache
1335-
// hits (near no-ops) and failures re-fail fast, yielding cleanly
1336-
// attributed per-test diagnostics without sacrificing parallelism.
1335+
// per-test loop below re-drives each goal so a failure is attributed to
1336+
// exactly one test.
1337+
//
1338+
// ...but ONLY when this bulk build failed. A re-drive was assumed to be
1339+
// a near no-op, and it is not: a drive re-emits build.ninja, rewrites
1340+
// compile_commands.json, spawns ninja and re-validates the runtime
1341+
// closure. Measured on the 83-test suite AFTER the rule E fix, that is
1342+
// still ~39ms x 83 = 3.2s of a 5.3s hot run — spent re-asking a question
1343+
// the bulk build just answered for every test at once.
1344+
//
1345+
// `-k 0` means the bulk exit code is 0 IFF every selected goal built, so
1346+
// it carries exactly the information the loop was re-deriving. When it
1347+
// is non-zero the loop runs as before and each failure still names its
1348+
// own test.
1349+
bool bulkBuiltEverything = false;
13371350
{
13381351
mcpp::build::BuildOptions bulk;
13391352
bulk.keepGoing = true;
@@ -1343,7 +1356,7 @@ export int run_tests(std::span<const std::string> passthrough,
13431356
bulk.ninjaTargets.push_back(lu.output.generic_string());
13441357
if (!bulk.ninjaTargets.empty()) {
13451358
auto tBulk = std::chrono::steady_clock::now();
1346-
(void)backend->build(ctx->plan, bulk);
1359+
bulkBuiltEverything = backend->build(ctx->plan, bulk).has_value();
13471360
summary.buildMs += std::chrono::duration_cast<std::chrono::milliseconds>(
13481361
std::chrono::steady_clock::now() - tBulk).count();
13491362
}
@@ -1374,6 +1387,117 @@ export int run_tests(std::span<const std::string> passthrough,
13741387
}
13751388
}
13761389

1390+
// How many test binaries run at once.
1391+
//
1392+
// The tests themselves were never the slow part — MEASURED on the 83-test
1393+
// suite, the whole run phase is 1.8s against a 190s total — so this is the
1394+
// tail, not the fix. It is still worth having: after the build-side work
1395+
// (rule E, the per-test re-drive) the run phase is HALF of what is left.
1396+
//
1397+
// ONE test runs in the foreground, unbuffered. That is the debugging case:
1398+
// a single long test streaming its progress is worth more than the ~0ms
1399+
// concurrency would save on it, and capturing would hold that output back
1400+
// until the test ended — including when it hangs, which is exactly when a
1401+
// reader needs it.
1402+
const int runJobs = [&] {
1403+
int j = mcpp::build::schedule::resolve_jobs(ctx->manifest);
1404+
if (j <= 0) j = static_cast<int>(std::thread::hardware_concurrency());
1405+
return j > 0 ? j : 1;
1406+
}();
1407+
1408+
struct Runnable {
1409+
std::string name;
1410+
std::vector<std::string> argv;
1411+
std::vector<std::pair<std::string, std::string>> env;
1412+
std::chrono::steady_clock::time_point started;
1413+
};
1414+
std::vector<Runnable> runnable;
1415+
1416+
// Executes `list`, appending to `results` and emitting the per-test line.
1417+
//
1418+
// Output is CAPTURED whenever more than one test runs, and printed as one
1419+
// contiguous block when that test finishes. Streaming N tests straight to
1420+
// the terminal interleaves them line by line, which does not just look
1421+
// untidy — it makes a failing assertion unattributable, and the whole
1422+
// reason the per-test loop exists is attribution.
1423+
auto run_tests_now = [&](std::vector<Runnable>& list) {
1424+
if (list.empty()) return;
1425+
const bool capture = json || list.size() > 1;
1426+
const auto deadline = std::chrono::milliseconds(
1427+
static_cast<long long>(testOpts.timeoutSecs) * 1000);
1428+
const int workers = capture
1429+
? std::min<int>(runJobs, static_cast<int>(list.size())) : 1;
1430+
1431+
auto tRunPhase = std::chrono::steady_clock::now();
1432+
std::atomic<std::size_t> next{0};
1433+
std::mutex reportMutex;
1434+
1435+
auto worker = [&] {
1436+
for (;;) {
1437+
std::size_t i = next.fetch_add(1);
1438+
if (i >= list.size()) return;
1439+
auto& r = list[i];
1440+
1441+
bool timedOut = false;
1442+
int exitCode = 0;
1443+
std::string runOutput;
1444+
if (capture) {
1445+
auto rr = mcpp::platform::process::capture_exec_deadline(
1446+
r.argv, r.env, deadline, &timedOut);
1447+
exitCode = rr.exit_code;
1448+
runOutput = std::move(rr.output);
1449+
} else {
1450+
mcpp::ui::status("Running", std::format("bin/{}", r.name));
1451+
exitCode = mcpp::platform::process::run_exec_deadline(
1452+
r.argv, r.env, deadline, &timedOut);
1453+
}
1454+
auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(
1455+
std::chrono::steady_clock::now() - r.started).count();
1456+
1457+
std::scoped_lock lock(reportMutex);
1458+
if (timedOut) {
1459+
if (!json) mcpp::ui::plain(std::format(
1460+
"{} ... FAIL (timeout after {}s)", r.name, testOpts.timeoutSecs));
1461+
results.push_back({r.name, TestResult::St::RunFail, exitCode, {},
1462+
runOutput, ms, true});
1463+
} else if (exitCode == 0) {
1464+
if (!json) mcpp::ui::plain(std::format(
1465+
"{} ... ok ({:.2f}s)", r.name, static_cast<double>(ms) / 1000.0));
1466+
results.push_back({r.name, TestResult::St::Pass, 0, {},
1467+
runOutput, ms});
1468+
} else {
1469+
if (!json) mcpp::ui::plain(std::format(
1470+
"{} ... FAIL (exit {}, {:.2f}s)", r.name, exitCode,
1471+
static_cast<double>(ms) / 1000.0));
1472+
results.push_back({r.name, TestResult::St::RunFail, exitCode, {},
1473+
runOutput, ms});
1474+
}
1475+
// The captured output belongs directly under its own line, or
1476+
// it is attributable to nothing.
1477+
if (!json && capture && !runOutput.empty()) {
1478+
std::fputs(runOutput.c_str(), stdout);
1479+
if (runOutput.back() != '\n') std::fputc('\n', stdout);
1480+
}
1481+
std::fflush(stdout);
1482+
emit_json(results.back());
1483+
}
1484+
};
1485+
1486+
if (workers <= 1) {
1487+
worker();
1488+
} else {
1489+
std::vector<std::thread> pool;
1490+
pool.reserve(static_cast<std::size_t>(workers));
1491+
for (int w = 0; w < workers; ++w) pool.emplace_back(worker);
1492+
for (auto& t : pool) t.join();
1493+
}
1494+
// WALL time of the phase, not the sum of the per-test durations: with
1495+
// N running at once that sum exceeds the elapsed time and the summary
1496+
// would report a run phase longer than the whole command.
1497+
summary.runMs += std::chrono::duration_cast<std::chrono::milliseconds>(
1498+
std::chrono::steady_clock::now() - tRunPhase).count();
1499+
};
1500+
13771501
for (auto& lu : ctx->plan.linkUnits) {
13781502
if (!filter_match(lu)) continue;
13791503

@@ -1385,13 +1509,16 @@ export int run_tests(std::span<const std::string> passthrough,
13851509

13861510
mcpp::ui::status("Compiling", std::format("{} (test)", lu.targetName));
13871511

1388-
mcpp::build::BuildOptions bOpts;
1389-
bOpts.ninjaTargets = {lu.output.generic_string()};
1390-
bOpts.buildTimeoutSecs = static_cast<unsigned>(testOpts.buildTimeoutSecs);
1391-
auto tBuild = std::chrono::steady_clock::now();
1392-
auto b = backend->build(ctx->plan, bOpts);
1393-
summary.buildMs += std::chrono::duration_cast<std::chrono::milliseconds>(
1394-
std::chrono::steady_clock::now() - tBuild).count();
1512+
std::expected<mcpp::build::BuildResult, mcpp::build::BuildError> b{};
1513+
if (!bulkBuiltEverything) {
1514+
mcpp::build::BuildOptions bOpts;
1515+
bOpts.ninjaTargets = {lu.output.generic_string()};
1516+
bOpts.buildTimeoutSecs = static_cast<unsigned>(testOpts.buildTimeoutSecs);
1517+
auto tBuild = std::chrono::steady_clock::now();
1518+
b = backend->build(ctx->plan, bOpts);
1519+
summary.buildMs += std::chrono::duration_cast<std::chrono::milliseconds>(
1520+
std::chrono::steady_clock::now() - tBuild).count();
1521+
}
13951522
if (!b) {
13961523
if (!json) {
13971524
// The test's own diagnostics, right under its FAIL line — a
@@ -1418,7 +1545,6 @@ export int run_tests(std::span<const std::string> passthrough,
14181545
}
14191546

14201547
auto exe = ctx->outputDir / lu.output;
1421-
mcpp::ui::status("Running", std::format("bin/{}", lu.targetName));
14221548

14231549
std::vector<std::string> argv;
14241550
argv.push_back(exe.string());
@@ -1448,45 +1574,13 @@ export int run_tests(std::span<const std::string> passthrough,
14481574
}
14491575
}
14501576

1451-
// JSON mode captures the test's combined stdout+stderr into the
1452-
// record; human mode streams it to the terminal as before.
1453-
auto deadline = std::chrono::milliseconds(
1454-
static_cast<long long>(testOpts.timeoutSecs) * 1000);
1455-
bool timedOut = false;
1456-
int exitCode;
1457-
std::string runOutput;
1458-
auto tRun = std::chrono::steady_clock::now();
1459-
if (json) {
1460-
auto rr = mcpp::platform::process::capture_exec_deadline(
1461-
argv, childEnv, deadline, &timedOut);
1462-
exitCode = rr.exit_code;
1463-
runOutput = std::move(rr.output);
1464-
} else {
1465-
exitCode = mcpp::platform::process::run_exec_deadline(
1466-
argv, childEnv, deadline, &timedOut);
1467-
}
1468-
summary.runMs += std::chrono::duration_cast<std::chrono::milliseconds>(
1469-
std::chrono::steady_clock::now() - tRun).count();
1470-
1471-
if (timedOut) {
1472-
if (!json) mcpp::ui::plain(std::format("{} ... FAIL (timeout after {}s)",
1473-
lu.targetName, testOpts.timeoutSecs));
1474-
results.push_back({lu.targetName, TestResult::St::RunFail, exitCode, {},
1475-
std::move(runOutput), test_ms(), true});
1476-
} else if (exitCode == 0) {
1477-
if (!json) mcpp::ui::plain(std::format("{} ... ok ({:.2f}s)", lu.targetName,
1478-
static_cast<double>(test_ms()) / 1000.0));
1479-
results.push_back({lu.targetName, TestResult::St::Pass, 0, {},
1480-
std::move(runOutput), test_ms()});
1481-
} else {
1482-
if (!json) mcpp::ui::plain(std::format("{} ... FAIL (exit {}, {:.2f}s)",
1483-
lu.targetName, exitCode,
1484-
static_cast<double>(test_ms()) / 1000.0));
1485-
results.push_back({lu.targetName, TestResult::St::RunFail, exitCode, {},
1486-
std::move(runOutput), test_ms()});
1487-
}
1488-
emit_json(results.back());
1577+
runnable.push_back({lu.targetName, std::move(argv), std::move(childEnv),
1578+
tTest});
14891579
}
1580+
1581+
// Pass 2: run them. Concurrently unless there is exactly one — see
1582+
// `runJobs` for why the single-test case is deliberately different.
1583+
run_tests_now(runnable);
14901584
summary.elapsedMs = member_ms();
14911585

14921586
// 7. Summary.

0 commit comments

Comments
 (0)