From 22585f5994133f19fdccfe1e9320ae3f0c58d6aa Mon Sep 17 00:00:00 2001 From: SPeak Date: Mon, 28 Sep 2026 19:25:48 +0800 Subject: [PATCH 1/2] TEMPORARY, do not merge: time clangd's module BMI rebuild on real projects Instruments module preparation (per-module prime duration, the preparation window and clangd's CPU at both ends) in the clangd engine's report, has the conformance runner wait for preparation and record it under MCPPLS_MEASURE_PREPARATION, and adds a linux-x64 workflow timing self-mcpp, real-xlings and self-mcppls cold and warm. --- .github/workflows/tmp-bmi-timing.yml | 106 +++++++++++++++++++++++++++ src/bin/conformance.cpp | 33 +++++++++ src/engine/clangd.cpp | 60 ++++++++++++++- 3 files changed, 198 insertions(+), 1 deletion(-) create mode 100644 .github/workflows/tmp-bmi-timing.yml diff --git a/.github/workflows/tmp-bmi-timing.yml b/.github/workflows/tmp-bmi-timing.yml new file mode 100644 index 0000000..b3a4785 --- /dev/null +++ b/.github/workflows/tmp-bmi-timing.yml @@ -0,0 +1,106 @@ +name: TEMPORARY bmi rebuild timing + +# TEMPORARY, not for merge. How much of a cold start is clangd rebuilding the modules' BMIs +# (mcppls's module preparation) on real projects: each fixture cold, then warm on the same +# workspace and cache, with MCPPLS_MEASURE_PREPARATION set so the conformance runner waits for +# preparation to finish and records the clangd engine's preparationTiming. +on: + pull_request: + workflow_dispatch: + +concurrency: + group: tmp-bmi-timing-${{ github.ref }} + cancel-in-progress: true + +env: + XLINGS_NON_INTERACTIVE: '1' + PAYLOAD_CACHE: ${{ github.workspace }}/.payload-cache + +jobs: + timing: + name: bmi rebuild timing (linux-x64) + if: github.event_name == 'workflow_dispatch' || github.head_ref == 'tmp/bmi-rebuild-timing' + runs-on: ubuntu-24.04 + timeout-minutes: 180 + defaults: + run: + shell: bash + steps: + - uses: actions/checkout@v7 + - uses: ./.github/actions/setup-mcpp + - name: Build tools for the kit configure + run: | + sudo apt-get update -q && sudo apt-get install -y -q ninja-build libc6-dev linux-libc-dev + command -v cmake > /dev/null || sudo apt-get install -y -q cmake + - name: Cache upstream inputs + uses: actions/cache@v6 + with: + path: .payload-cache + key: payload-inputs-linux-x64-${{ hashFiles('packaging/payload.lock.json') }} + - name: Build the server and assemble the payload + run: | + set -euo pipefail + mcpp build --profile release + mcpp build -p devtools --profile release + mkdir -p cross stage + for exe in mcppls mcppls-conformance mcppls-mock-mcpp mcppls-mock-model mcppls-devtools; do + cp "$(find target tools/devtools/target -type f -name "$exe" -path '*/bin/*' -newer mcpp.toml | head -1)" cross/ + done + chmod +x cross/* + cross/mcppls-devtools payload --platform linux-x64 --server cross/mcppls --out payload --cache "$PAYLOAD_CACHE" + cross/mcppls-devtools payload --verify payload --json > /dev/null + cp cross/mcppls-conformance stage/ + - name: GCC 16 and the mcpp the mcpp repository asks for + run: | + set -euo pipefail + mcpp toolchain install gcc 16.1.0 + xlings install mcpp@2026.9.21.1 -y -g + xlings use mcpp "$MCPP_VERSION" + mcpp --version + - name: Cold and warm starts, preparation timed + env: + MCPPLS_MEASURE_PREPARATION: '1' + run: | + set -uo pipefail + results="$RUNNER_TEMP/bmi-timing" + mkdir -p "$results" + echo "nproc=$(nproc)" | tee "$results/host.txt" + for fixture in self-mcpp real-xlings self-mcppls; do + for start in cold warm; do + warm=(); [ "$start" = warm ] && warm=(--expect-warm) + stage/mcppls-conformance run --server payload/bin/mcppls --payload payload --fixture "conformance/fixtures/$fixture" \ + --workspace-dir "$RUNNER_TEMP/ws-$fixture" --cache-dir "$RUNNER_TEMP/cache-$fixture" --timeout 900 \ + --measure "$results/$fixture-$start.json" ${warm[@]+"${warm[@]}"} 2>&1 | tail -40 \ + || echo "::warning::$fixture $start: the runner reported failures (timing kept)" + done + done + - name: Summary + if: always() + run: | + python3 - "$RUNNER_TEMP/bmi-timing" <<'EOF' | tee -a "$GITHUB_STEP_SUMMARY" + import json, os, sys + d = sys.argv[1] + print("## BMI rebuild timing (linux-x64, " + open(os.path.join(d, "host.txt")).read().strip() + ")\n") + print("| fixture | start | ready s | first nav s | primed | prep window s | sum of primes s | clangd CPU in prep s | clangd CPU total s | CPU share | slowest modules |") + print("|---|---|---|---|---|---|---|---|---|---|---|") + def f(x): return "-" if x is None else f"{x:.1f}" + for fixture in ("self-mcpp", "real-xlings", "self-mcppls"): + for start in ("cold", "warm"): + p = os.path.join(d, f"{fixture}-{start}.json") + if not os.path.exists(p): + print(f"| {fixture} | {start} | missing |"); continue + m = json.load(open(p)) + timings = [e for e in (m.get("preparationTiming") or []) if e.get("engine") == "clangd"] + t = timings[0]["timing"] if timings else {} + b, e, now = t.get("clangdCpuAtBegin"), t.get("clangdCpuAtEnd"), t.get("clangdCpuNow") + prep = (e - b) if (b is not None and e is not None) else None + share = f"{100 * prep / now:.0f}%" if (prep is not None and now) else "-" + slow = ", ".join(f"{x['module']} {x['seconds']:.1f}" for x in t.get("modules", [])[:3]) + print(f"| {fixture} | {start} | {f(m.get('ready'))} | {f(m.get('first-navigation'))} | {t.get('primedModules', '-')} | " + f"{f(t.get('windowSeconds'))} | {f(t.get('sumSeconds'))} | {f(prep)} | {f(now)} | {share} | {slow} |") + EOF + - uses: actions/upload-artifact@v7 + if: always() + with: + name: bmi-timing + path: ${{ runner.temp }}/bmi-timing diff --git a/src/bin/conformance.cpp b/src/bin/conformance.cpp index a464816..37c821c 100644 --- a/src/bin/conformance.cpp +++ b/src/bin/conformance.cpp @@ -2098,6 +2098,35 @@ int run(Options options) { measured.push_back(Json { { "id", id }, { "kind", check.value("kind", std::string {}) }, { "ok", ok }, { "seconds", seconds }, { "since-start", std::chrono::duration(Clock::now() - begin).count() }, { "detail", detail } }); } + // TEMPORARY (BMI rebuild timing, not for merge): with MCPPLS_MEASURE_PREPARATION set, wait for every + // clangd engine's module preparation to finish (up to 15 minutes) and keep what its report says about it. + Json preparationTiming = nullptr; + const auto measurePreparationWait = Clock::now(); + if (!options.measureFile.empty() && mcppls::platform::env::get("MCPPLS_MEASURE_PREPARATION").value_or("").size() > 0) { + const auto deadline = Clock::now() + std::chrono::minutes { 15 }; + while (true) { + auto answer = client.request("cxxModules/report", Json::object(), std::chrono::seconds { 30 }); + bool settled { answer.has_value() }; + Json timings = Json::array(); + if (answer) { + for (const auto& root : (*answer).value("roots", Json::array())) { + for (const auto& engine : root.value("engines", Json::array())) { + const Json details = engine.value("details", Json::object()); + if (!details.contains("preparationTiming")) continue; + const Json preparation = details.value("preparation", Json::object()); + if (preparation.value("running", 0) > 0 || preparation.value("done", 0) < preparation.value("wanted", 0)) settled = false; + timings.push_back(Json { { "engine", engine.value("name", std::string {}) }, { "preparation", preparation }, + { "timing", details["preparationTiming"] } }); + } + } + } + if (timings.empty() && answer) (void)fs::write_file(options.measureFile + ".report.json", answer->dump(2)); + preparationTiming = std::move(timings); + if (settled || Clock::now() >= deadline) break; + client.drain(std::chrono::milliseconds { 2000 }); + } + } + const double preparationWaitSeconds { std::chrono::duration(Clock::now() - measurePreparationWait).count() }; runner.finish(); client.stop(); Json firstNavigation = nullptr; @@ -2140,6 +2169,10 @@ int run(Options options) { summary["first-diagnostics"] = since(client.firstDiagnostics); summary["first-navigation"] = firstNavigation; summary["checks"] = measured; + summary["beginEpochMs"] = std::chrono::duration_cast(std::chrono::system_clock::now().time_since_epoch()).count() + - static_cast(std::chrono::duration(Clock::now() - begin).count()); + summary["preparationTiming"] = preparationTiming; + summary["preparationWaitSeconds"] = preparationWaitSeconds; if (auto written = fs::write_file(options.measureFile, summary.dump(2) + "\n"); !written) say("conformance: cannot write {}", options.measureFile); } if (!options.keep && !reused) fs::remove_all(scratch); diff --git a/src/engine/clangd.cpp b/src/engine/clangd.cpp index e1d4e77..8c2eadd 100644 --- a/src/engine/clangd.cpp +++ b/src/engine/clangd.cpp @@ -137,7 +137,49 @@ class ClangdEngine final : public Engine { std::map> primeDeadlines_; std::map> heldPrimeUnits_; std::optional lastPrimeProgressAt_; - std::map> moduleSources_; // importable module -> the unit providing it, from the plan + // TEMPORARY (BMI rebuild timing, not for merge): how long clangd took to build each module a prime + // unit imports -- from its `import M;` didOpen to its first diagnostics -- and the window the whole + // preparation spans, with clangd's CPU seconds at both ends. + struct PrimeTiming { + std::map> startedAt; + std::vector> seconds; // module, seconds, in finishing order + std::optional begin; + std::optional end; // the last time preparation went idle + std::int64_t beginEpochMs { 0 }; + std::int64_t endEpochMs { 0 }; + std::optional cpuAtBegin; + std::optional cpuAtEnd; + } primeTiming_; + std::optional clangd_cpu_now_() const { + auto reader = process_ ? process_->cpu_reader() : std::function()> {}; + return reader ? reader() : std::nullopt; + } + static std::int64_t epoch_ms_() { + return std::chrono::duration_cast(std::chrono::system_clock::now().time_since_epoch()).count(); + } + Json prime_timing_json_() const { + auto sorted = primeTiming_.seconds; + std::ranges::sort(sorted, std::greater {}, [](const auto& entry) { return entry.second; }); + double sum { 0 }; + Json modules = Json::array(); + for (const auto& [name, seconds] : sorted) { + sum += seconds; + modules.push_back(Json { { "module", name }, { "seconds", seconds } }); + } + auto optional = [](const std::optional& value) { return value ? Json(*value) : Json(nullptr); }; + const bool ended { primeTiming_.begin && primeTiming_.end && *primeTiming_.end >= *primeTiming_.begin }; + return Json { { "primedModules", primeTiming_.seconds.size() }, + { "unfinished", primeTiming_.startedAt.size() }, + { "sumSeconds", sum }, + { "windowSeconds", ended ? Json(std::chrono::duration(*primeTiming_.end - *primeTiming_.begin).count()) : Json(nullptr) }, + { "beginEpochMs", primeTiming_.beginEpochMs }, + { "endEpochMs", primeTiming_.endEpochMs }, + { "clangdCpuAtBegin", optional(primeTiming_.cpuAtBegin) }, + { "clangdCpuAtEnd", optional(primeTiming_.cpuAtEnd) }, + { "clangdCpuNow", optional(clangd_cpu_now_()) }, + { "modules", std::move(modules) } }; + } + std::map> moduleSources_; // importable module -> the unit providing it, from the plan // clangd's persistent module cache as the plan found it (cached_bmis), read the first time a // module becomes ready for preparation and not again until the next plan. std::optional, std::less<>>> startupBmis_; @@ -446,6 +488,7 @@ class ClangdEngine final : public Engine { { "doomedModules", std::move(doomed) }, { "filesRoutedToOwnEngine", std::move(doomedFiles) }, { "stdFromSemanticKit", stdFromKit_ }, + { "preparationTiming", prime_timing_json_() }, { "preparation", Json { { "done", done }, { "wanted", wanted }, { "running", primer_.running() }, { "limit", preparation_limit(std::thread::hardware_concurrency(), mcppls::os::FAMILY == mcppls::os::Family::macos, awaitingDiagnostics_.size()) } } }, @@ -3647,6 +3690,12 @@ class ClangdEngine final : public Engine { note_database_read_(); primeModuleByPath_[base::path_key(module->primeFile)] = module->name; primeDeadlines_[module->name] = Clock::now() + std::chrono::minutes { 3 }; + if (!primeTiming_.begin) { + primeTiming_.begin = Clock::now(); + primeTiming_.beginEpochMs = epoch_ms_(); + primeTiming_.cpuAtBegin = clangd_cpu_now_(); + } + primeTiming_.startedAt[module->name] = Clock::now(); } host_->status_changed(); } @@ -3664,7 +3713,16 @@ class ClangdEngine final : public Engine { heldPrimeUnits_.emplace(pathKey, canonical); primer_.finish(module); lastPrimeProgressAt_ = Clock::now(); + if (const auto started = primeTiming_.startedAt.find(module); started != primeTiming_.startedAt.end()) { + primeTiming_.seconds.emplace_back(module, std::chrono::duration(Clock::now() - started->second).count()); + primeTiming_.startedAt.erase(started); + } pump_primer_(); + if (!primer_.busy()) { + primeTiming_.end = Clock::now(); + primeTiming_.endEpochMs = epoch_ms_(); + primeTiming_.cpuAtEnd = clangd_cpu_now_(); + } release_prime_units_if_idle_(); if (!primer_.busy()) pump_implementations_(Clock::now()); return true; From 39cbf25b78af917e2784739d4d94246c2eeadabd Mon Sep 17 00:00:00 2001 From: SPeak Date: Mon, 28 Sep 2026 20:02:08 +0800 Subject: [PATCH 2/2] TEMPORARY: round 2, self-mcpp with clangd's module log and .pcm snapshots per start Once preparation is idle and MCPPLS_MEASURE_PREPARATION is set, the clangd engine writes its log ring to /clangd-ring.log; the workflow keeps it, the server logs and a .pcm snapshot after the cold and the warm start, to tell whether the warm start built BMIs again. --- .github/workflows/tmp-bmi-timing.yml | 21 +++++++++++++++++++-- src/engine/clangd.cpp | 10 +++++++++- 2 files changed, 28 insertions(+), 3 deletions(-) diff --git a/.github/workflows/tmp-bmi-timing.yml b/.github/workflows/tmp-bmi-timing.yml index b3a4785..1700c8b 100644 --- a/.github/workflows/tmp-bmi-timing.yml +++ b/.github/workflows/tmp-bmi-timing.yml @@ -65,13 +65,20 @@ jobs: results="$RUNNER_TEMP/bmi-timing" mkdir -p "$results" echo "nproc=$(nproc)" | tee "$results/host.txt" - for fixture in self-mcpp real-xlings self-mcppls; do + # Round 2: self-mcpp only, with clangd's own log ("Built module" / "Reusing module") and a + # snapshot of every .pcm after each start, to tell whether the warm start rebuilt BMIs. + for fixture in self-mcpp; do for start in cold warm; do warm=(); [ "$start" = warm ] && warm=(--expect-warm) stage/mcppls-conformance run --server payload/bin/mcppls --payload payload --fixture "conformance/fixtures/$fixture" \ --workspace-dir "$RUNNER_TEMP/ws-$fixture" --cache-dir "$RUNNER_TEMP/cache-$fixture" --timeout 900 \ --measure "$results/$fixture-$start.json" ${warm[@]+"${warm[@]}"} 2>&1 | tail -40 \ || echo "::warning::$fixture $start: the runner reported failures (timing kept)" + log=$(find "$RUNNER_TEMP/cache-$fixture" -name clangd-ring.log | head -1) + [ -n "$log" ] && cp "$log" "$results/$fixture-$start-clangd.log" + find "$RUNNER_TEMP/cache-$fixture" "$RUNNER_TEMP/ws-$fixture" -name '*.pcm' -printf '%T@ %s %P\n' | sort > "$results/$fixture-$start-pcm.txt" + mkdir -p "$results/$fixture-$start-server-logs" + find "$RUNNER_TEMP/cache-$fixture" -path '*/logs/*' -type f -exec cp {} "$results/$fixture-$start-server-logs/" \; done done - name: Summary @@ -84,7 +91,7 @@ jobs: print("| fixture | start | ready s | first nav s | primed | prep window s | sum of primes s | clangd CPU in prep s | clangd CPU total s | CPU share | slowest modules |") print("|---|---|---|---|---|---|---|---|---|---|---|") def f(x): return "-" if x is None else f"{x:.1f}" - for fixture in ("self-mcpp", "real-xlings", "self-mcppls"): + for fixture in ("self-mcpp",): for start in ("cold", "warm"): p = os.path.join(d, f"{fixture}-{start}.json") if not os.path.exists(p): @@ -99,6 +106,16 @@ jobs: print(f"| {fixture} | {start} | {f(m.get('ready'))} | {f(m.get('first-navigation'))} | {t.get('primedModules', '-')} | " f"{f(t.get('windowSeconds'))} | {f(t.get('sumSeconds'))} | {f(prep)} | {f(now)} | {share} | {slow} |") EOF + for start in cold warm; do + log="$RUNNER_TEMP/bmi-timing/self-mcpp-$start-clangd.log" + pcm="$RUNNER_TEMP/bmi-timing/self-mcpp-$start-pcm.txt" + echo "" + echo "self-mcpp $start: clangd log $( [ -f "$log" ] && wc -l < "$log" || echo missing) lines;" \ + "Built module $(grep -c 'Built module' "$log" 2>/dev/null || true)," \ + "Reusing persistent module $(grep -c 'Reusing persistent module' "$log" 2>/dev/null || true)," \ + "Reusing module $(grep -c 'Reusing module' "$log" 2>/dev/null || true);" \ + ".pcm files $(wc -l < "$pcm" 2>/dev/null || echo 0)" + done | tee -a "$GITHUB_STEP_SUMMARY" - uses: actions/upload-artifact@v7 if: always() with: diff --git a/src/engine/clangd.cpp b/src/engine/clangd.cpp index 8c2eadd..49b3cf3 100644 --- a/src/engine/clangd.cpp +++ b/src/engine/clangd.cpp @@ -168,7 +168,15 @@ class ClangdEngine final : public Engine { } auto optional = [](const std::optional& value) { return value ? Json(*value) : Json(nullptr); }; const bool ended { primeTiming_.begin && primeTiming_.end && *primeTiming_.end >= *primeTiming_.begin }; - return Json { { "primedModules", primeTiming_.seconds.size() }, + // Whether clangd reused its module files or built them again is in its own log ("Built module", + // "Reusing module"): once preparation is idle, the ring goes to the cache directory for the workflow. + Json logFile = nullptr; + if (host_ != nullptr && !primer_.busy() && !platform::env::get("MCPPLS_MEASURE_PREPARATION").value_or("").empty()) { + const std::string path { base::join_path(host_->cache_directory(), "clangd-ring.log") }; + if (platform::fs::write_file(path, logRing_->text())) logFile = path; + } + return Json { { "clangdLogFile", logFile }, + { "primedModules", primeTiming_.seconds.size() }, { "unfinished", primeTiming_.startedAt.size() }, { "sumSeconds", sum }, { "windowSeconds", ended ? Json(std::chrono::duration(*primeTiming_.end - *primeTiming_.begin).count()) : Json(nullptr) },