From abf0601dc2b58c7c13b3fcb6d511818152453bdb Mon Sep 17 00:00:00 2001
From: sunrisepeak <speakshen@163.com>
Date: Wed, 24 Jun 2026 05:52:14 +0800
Subject: [PATCH] feat(log): timestamp --verbose output + ScopedTimer for
 first-init steps
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Diagnose first-run long hangs: every --verbose line now carries a wall-clock
timestamp ([VERBOSE <ts>]), and the one-time bootstrap steps (sandbox layout,
patchelf, ninja) are wrapped in a ScopedTimer logging 'start' + 'done (Δ=<ms>ms)'.
Logged to ~/.mcpp/log/mcpp.log always (already timestamped) + stderr under
--verbose, so a slow step is attributable after the fact. Toolchain install
already logs verbose (now timestamped). WS5 of the index/offline-first plan.
---
 src/log.cppm    | 41 +++++++++++++++++++++++++++++++++++++++--
 src/xlings.cppm |  4 ++++
 2 files changed, 43 insertions(+), 2 deletions(-)

diff --git a/src/log.cppm b/src/log.cppm
index 6dbbcf10..7ee20714 100644
--- a/src/log.cppm
+++ b/src/log.cppm
@@ -43,6 +43,22 @@ void set_verbose(bool v);
 bool is_verbose();
 void verbose(std::string_view tag, std::string_view message);
 
+// Scoped verbose timer for diagnosing slow steps (e.g. first-run init / bootstrap
+// hangs). Logs "<label>: start" on construction and "<label>: done (Δ=<ms>ms)" on
+// destruction, via verbose() — always to the timestamped log file
+// (~/.mcpp/log/mcpp.log), and to stderr under --verbose. Cheap: two log lines.
+struct ScopedTimer {
+    std::string tag;
+    std::string label;
+    std::chrono::steady_clock::time_point t0;
+    ScopedTimer(std::string_view tag_, std::string_view label_);
+    ~ScopedTimer();
+    ScopedTimer(const ScopedTimer&) = delete;
+    ScopedTimer& operator=(const ScopedTimer&) = delete;
+    // Emit an intermediate checkpoint: "<label>: <note> (+<ms>ms)".
+    void mark(std::string_view note) const;
+};
+
 // Check if a level is enabled (avoid constructing expensive messages).
 bool is_enabled(Level l);
 
@@ -136,8 +152,12 @@ void write_log(Level level, std::string_view tag, std::string_view message) {
 }
 
 void write_stderr(std::string_view tag, std::string_view message) {
-    // Dim gray for verbose output so it doesn't compete with ui::status
-    std::fprintf(stderr, "\033[2m[VERBOSE] %.*s: %.*s\033[0m\n",
+    // Dim gray for verbose output so it doesn't compete with ui::status.
+    // Carry the wall-clock timestamp so a long first-run hang is attributable
+    // to a specific step from the live --verbose stream (the log file already
+    // has it). Grep-friendly: "[VERBOSE <ts>]".
+    std::fprintf(stderr, "\033[2m[VERBOSE %s] %.*s: %.*s\033[0m\n",
+        timestamp().c_str(),
         static_cast<int>(tag.size()), tag.data(),
         static_cast<int>(message.size()), message.data());
 }
@@ -212,4 +232,21 @@ void verbose(std::string_view tag, std::string_view message) {
     }
 }
 
+ScopedTimer::ScopedTimer(std::string_view tag_, std::string_view label_)
+    : tag(tag_), label(label_), t0(std::chrono::steady_clock::now()) {
+    verbose(tag, std::format("{}: start", label));
+}
+
+ScopedTimer::~ScopedTimer() {
+    auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(
+                  std::chrono::steady_clock::now() - t0).count();
+    verbose(tag, std::format("{}: done (Δ={}ms)", label, ms));
+}
+
+void ScopedTimer::mark(std::string_view note) const {
+    auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(
+                  std::chrono::steady_clock::now() - t0).count();
+    verbose(tag, std::format("{}: {} (+{}ms)", label, note, ms));
+}
+
 } // namespace mcpp::log
diff --git a/src/xlings.cppm b/src/xlings.cppm
index 55abb659..3730220f 100644
--- a/src/xlings.cppm
+++ b/src/xlings.cppm
@@ -16,6 +16,7 @@ export module mcpp.xlings;
 import std;
 import mcpp.pm.compat;
 import mcpp.platform;
+import mcpp.log;
 
 export namespace mcpp::xlings {
 
@@ -1075,6 +1076,7 @@ void ensure_init(const Env& env, bool quiet) {
 
     if (!quiet)
         print_status("Initialize", "mcpp sandbox layout (one-time)");
+    mcpp::log::ScopedTimer _t_init("init", "sandbox layout (xlings self init)");
     std::string cmd;
     if constexpr (mcpp::platform::is_windows) {
         mcpp::platform::env::set("XLINGS_HOME", env.home.string());
@@ -1122,6 +1124,7 @@ void ensure_patchelf(const Env& env, bool quiet,
 
     if (!quiet)
         print_status("Bootstrap", "patchelf into mcpp sandbox (one-time)");
+    mcpp::log::ScopedTimer _t_pe("init", std::format("bootstrap patchelf@{}", pinned::kPatchelfVersion));
     int rc = install_with_progress(env,
         std::format("xim:patchelf@{}", pinned::kPatchelfVersion), cb, quiet);
     if (rc != 0 && !quiet) {
@@ -1148,6 +1151,7 @@ void ensure_ninja(const Env& env, bool quiet,
     }
     if (!quiet)
         print_status("Bootstrap", "ninja into mcpp sandbox (one-time)");
+    mcpp::log::ScopedTimer _t_ninja("init", std::format("bootstrap ninja@{}", pinned::kNinjaVersion));
     int rc = install_with_progress(env,
         std::format("xim:ninja@{}", pinned::kNinjaVersion), cb, quiet);
     if (rc != 0 && !quiet) {