[DO NOT MERGE] temporary: time clangd's module BMI rebuild on real projects

.github/workflows/tmp-bmi-timing.yml

@@ -0,0 +1,123 @@
+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"
+          # 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
+        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",):
+              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
+          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:
+          name: bmi-timing
+          path: ${{ runner.temp }}/bmi-timing

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<double>(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<double>(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::milliseconds>(std::chrono::system_clock::now().time_since_epoch()).count()
+                                  - static_cast<std::int64_t>(std::chrono::duration<double, std::milli>(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);

src/engine/clangd.cpp

@@ -137,7 +137,57 @@ class ClangdEngine final : public Engine {
     std::map<std::string, Clock::time_point, std::less<>> primeDeadlines_;
     std::map<std::string, std::string, std::less<>> heldPrimeUnits_;
     std::optional<Clock::time_point> lastPrimeProgressAt_;
-    std::map<std::string, std::string, std::less<>> 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<std::string, Clock::time_point, std::less<>> startedAt;
+        std::vector<std::pair<std::string, double>> seconds;   // module, seconds, in finishing order
+        std::optional<Clock::time_point> begin;
+        std::optional<Clock::time_point> end;                  // the last time preparation went idle
+        std::int64_t beginEpochMs { 0 };
+        std::int64_t endEpochMs { 0 };
+        std::optional<double> cpuAtBegin;
+        std::optional<double> cpuAtEnd;
+    } primeTiming_;
+    std::optional<double> clangd_cpu_now_() const {
+        auto reader = process_ ? process_->cpu_reader() : std::function<std::optional<double>()> {};
+        return reader ? reader() : std::nullopt;
+    }
+    static std::int64_t epoch_ms_() {
+        return std::chrono::duration_cast<std::chrono::milliseconds>(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<double>& value) { return value ? Json(*value) : Json(nullptr); };
+        const bool ended { primeTiming_.begin && primeTiming_.end && *primeTiming_.end >= *primeTiming_.begin };
+        // 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<double>(*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<std::string, std::string, std::less<>> 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::map<std::string, std::vector<std::string>, std::less<>>> startupBmis_;
@@ -446,6 +496,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 +3698,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 +3721,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<double>(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;