Refactor systemd boot time collection
This commit refactor the logic here so that it's more clear and restrict
systemd time to current bmc node only instead of broadcasting to all bmc
nodes.
In addition, this commit avoids overwriting the checkpoints by only
systemd checkpoints multiple times at boot or service restart.
Lastly, this commit also merges FirmwarePlusLoader into firmware time
so that we don't diverge in the SLO metric naming.
Test result:
Power cycle the machine and restart the service manually.
https://paste.googleplex.com/5958365410492416?raw
Google-Bug-Id: 386135751
Google-Bug-Id: 386135750
Change-Id: I1b57eddc3110793e6b76f8c7aac68c4b866c5979
Signed-off-by: Medicine Yeh <medicineyeh@google.com>
diff --git a/include/systemd_handler.hpp b/include/systemd_handler.hpp
index 9d874f7..f42115d 100644
--- a/include/systemd_handler.hpp
+++ b/include/systemd_handler.hpp
@@ -48,7 +48,8 @@
* @param api Shared pointer to the central boot time monitoring API.
*/
Handler(std::shared_ptr<sdbusplus::asio::connection> conn,
- std::shared_ptr<btm::api::IBoottimeApi> api);
+ std::shared_ptr<btm::api::IBoottimeApi> api,
+ btm::NodeConfig bmcNode);
private:
/** @brief Interval for polling systemd properties until boot is finished.
@@ -65,8 +66,26 @@
* @param ec Boost error code from the timer operation.
* @param conn Shared pointer to the sdbusplus ASIO connection.
*/
- void CheckBmcFinish(const boost::system::error_code& ec,
- std::shared_ptr<sdbusplus::asio::connection>& conn);
+ void UpdateBmcCheckpoints(const boost::system::error_code& ec);
+
+ /**
+ * @brief Queries a specific timestamp property from systemd via D-Bus.
+ *
+ * @param[in] propertyName The name of the systemd property to query.
+ *
+ * @return A `std::optional<uint64_t>` containing the timestamp on success,
+ * or an empty optional on failure.
+ */
+ std::optional<uint64_t>
+ QuerySystemdTimestamp(std::string_view propertyName);
+
+ /**
+ * @brief Reschedules the timer to continue polling systemd.
+ *
+ * This helper function resets the polling timer to fire again after the
+ * predefined interval, triggering another call to UpdateBmcCheckpoints.
+ */
+ void RestartPolling();
#ifdef NPCM7XX_OR_NEWER
/**
@@ -94,6 +113,10 @@
/** @brief ASIO timer used to periodically check for systemd boot
* completion. */
boost::asio::steady_timer mBMCFinishTimer;
+ /** @brief Shared pointer to the sdbusplus D-Bus connection. */
+ std::shared_ptr<sdbusplus::asio::connection> mDbusConn;
+ /** @brief Configuration for the node being monitored. */
+ btm::NodeConfig mNode;
};
} // namespace systemd
} // namespace boot_time_monitor
diff --git a/src/main.cpp b/src/main.cpp
index 2ae2436..33920b1 100644
--- a/src/main.cpp
+++ b/src/main.cpp
@@ -90,6 +90,18 @@
return 1;
}
}
+ if (hostCount < 0)
+ {
+ fmt::print(stderr, "hostCount({}) must be greater than zero.\n",
+ hostCount);
+ return 1;
+ }
+ if (bmcCount < 0)
+ {
+ fmt::print(stderr, "bmcCount({}) must be greater than zero.\n",
+ bmcCount);
+ return 1;
+ }
boost::asio::io_service io;
auto conn = std::make_shared<sdbusplus::asio::connection>(io);
@@ -143,7 +155,8 @@
bus, nodeConfig, btm::gen::GenDbusConfig(nodeConfig), api));
}
- btm::systemd::Handler systemdHandler(conn, api);
+ // Set up async systemd handler to update checkpoints/durations on this bmc.
+ btm::systemd::Handler systemdHandler(conn, api, bmcNodeConfigs[0]);
io.run();
diff --git a/src/systemd_handler.cpp b/src/systemd_handler.cpp
index 77fe4c4..aca8ec5 100644
--- a/src/systemd_handler.cpp
+++ b/src/systemd_handler.cpp
@@ -1,12 +1,13 @@
#include "systemd_handler.hpp"
-#include "log.hpp"
+#include "log.hpp" // provide btm::log::LogIfError
#include <fmt/printf.h>
#include <boost/interprocess/file_mapping.hpp>
#include <boost/interprocess/mapped_region.hpp>
+#include <fstream>
#include <regex>
namespace boot_time_monitor
@@ -24,223 +25,248 @@
"UserspaceTimestampMonotonic";
constexpr std::string_view kSystemdFinishTime = "FinishTimestampMonotonic";
-constexpr int64_t kMillisecondPerSecond = 1000;
-
-struct SystemdTimestamp
+struct SystemdTimestamps
{
- uint64_t firmware;
- uint64_t loader;
- uint64_t kernel;
- uint64_t initRD;
- uint64_t userspace;
- uint64_t finish;
+ uint64_t firmware = 0;
+ uint64_t loader = 0;
+ uint64_t kernel = 0;
+ uint64_t initRD = 0;
+ uint64_t userspace = 0;
+ uint64_t finish = 0;
};
-struct SystemdDuration
+// Support negative duration if needed.
+struct SystemdDurations
{
- int64_t firmware;
- int64_t loader;
- int64_t kernel;
- int64_t initRD;
- int64_t userspace;
+ int64_t firmware = 0;
+ int64_t loader = 0;
+ int64_t kernel = 0;
+ int64_t initRD = 0;
+ int64_t userspace = 0;
};
namespace
{
-// How to calculate duration for each stage:
-// https://github.com/systemd/systemd/blob/82b7bf8c1c8c6ded6f56b43998c803843a3b944b/src/analyze/analyze-time-data.c#L176-L186
-// Special calculation for kernel duration:
-// https://github.com/systemd/systemd/blob/82b7bf8c1c8c6ded6f56b43998c803843a3b944b/src/analyze/analyze-time-data.c#L84-L87
-inline SystemdDuration CalculateSystemdDuration(SystemdTimestamp times)
+// --- Helper Functions ---
+
+/**
+ * @brief Calculates boot stage durations from systemd timestamps.
+ * @param times A struct containing all collected monotonic timestamps.
+ * @return A struct containing the calculated duration for each stage in ms.
+ *
+ * The calculation logic is based on systemd-analyze:
+ * https://github.com/systemd/systemd/blob/82b7bf8c1c8c6ded6f56b43998c803843a3b944b/src/analyze/analyze-time-data.c#L176-L186
+ * Special calculation for kernel duration:
+ * https://github.com/systemd/systemd/blob/82b7bf8c1c8c6ded6f56b43998c803843a3b944b/src/analyze/analyze-time-data.c#L84-L87
+ */
+SystemdDurations CalculateSystemdDuration(const SystemdTimestamps& times)
{
- int64_t firmware = static_cast<int64_t>(times.firmware);
- int64_t loader = static_cast<int64_t>(times.loader);
- int64_t initRD = static_cast<int64_t>(times.initRD);
- int64_t userspace = static_cast<int64_t>(times.userspace);
- int64_t finish = static_cast<int64_t>(times.finish);
- SystemdDuration durations;
- durations.kernel = userspace;
+ // Durations are calculated by subtracting the start times of subsequent
+ // stages. Cast to signed to prevent underflow if timestamps are out of
+ // order.
+ auto to_ms = [](int64_t us) { return us > 0 ? us / 1000 : 0; };
- if (firmware != 0)
- {
- durations.firmware = firmware - loader;
- }
+ int64_t firmware_us = static_cast<int64_t>(times.firmware);
+ int64_t loader_us = static_cast<int64_t>(times.loader);
+ int64_t initRD_us = static_cast<int64_t>(times.initRD);
+ int64_t userspace_us = static_cast<int64_t>(times.userspace);
+ int64_t finish_us = static_cast<int64_t>(times.finish);
- if (loader != 0)
- {
- durations.loader = loader;
- }
+ SystemdDurations durations;
+ durations.firmware = to_ms(firmware_us - loader_us);
+ durations.loader = to_ms(loader_us);
+ // Kernel time ends when initrd is done, or when userspace starts if no
+ // initrd.
+ durations.kernel = (initRD_us > 0) ? to_ms(initRD_us) : to_ms(userspace_us);
+ durations.initRD = (initRD_us > 0) ? to_ms(userspace_us - initRD_us) : 0;
+ durations.userspace = to_ms(finish_us - userspace_us);
- if (initRD > 0)
- {
- durations.kernel = initRD;
- }
-
- if (initRD != 0)
- {
- durations.initRD = userspace - initRD;
- }
-
- if (userspace != 0)
- {
- durations.userspace = finish - userspace;
- }
return durations;
}
-inline std::string convertName(std::string_view name)
+/**
+ * @brief Removes the "TimestampMonotonic" suffix from a property name.
+ * @param name The full D-Bus property name.
+ * @return The base name for the boot stage.
+ */
+std::string GetStageName(std::string_view name)
{
- return std::regex_replace(std::string(name),
- std::regex("TimestampMonotonic"), "");
+ constexpr std::string_view suffix = "TimestampMonotonic";
+ if (name.ends_with(suffix))
+ {
+ name.remove_suffix(suffix.length());
+ }
+ return std::string(name);
}
} // namespace
+// --- Class Implementation ---
+
Handler::Handler(std::shared_ptr<sdbusplus::asio::connection> conn,
- std::shared_ptr<btm::api::IBoottimeApi> api) :
- mApi(std::move(api)), mBMCFinishTimer(conn->get_io_context())
+ std::shared_ptr<btm::api::IBoottimeApi> api,
+ btm::NodeConfig bmcNode) :
+ mApi(std::move(api)), mBMCFinishTimer(conn->get_io_context()),
+ mDbusConn(std::move(conn)), mNode(std::move(bmcNode))
{
- mBMCFinishTimer.expires_after(std::chrono::seconds(0));
- mBMCFinishTimer.async_wait(
- [this, &conn](const boost::system::error_code& ec) {
- CheckBmcFinish(ec, conn);
- });
-}
-
-void Handler::CheckBmcFinish(const boost::system::error_code& ec,
- std::shared_ptr<sdbusplus::asio::connection>& conn)
-{
- if (ec == boost::asio::error::operation_aborted)
+ // On startup, check if the system has already finished booting.
+ if (auto finishTime = QuerySystemdTimestamp(kSystemdFinishTime);
+ finishTime && *finishTime > 0)
{
- fmt::print(stderr,
- "[CheckBmcFinish] BmcFinishTimer is being "
- "canceled, Error: {}\n",
- ec.message().c_str());
- return;
- }
-
- if (ec)
- {
- fmt::print(stderr, "[CheckBmcFinish] Timer Error: {}\n",
- ec.message().c_str());
- return;
- }
-
- // The raw pointer here is safe since it points to an existing instance
- // instead of allocating a memory space.
- // We can't use `std::share_ptr<uint64_t>(×.firmware)` because the
- // `times` will free its space while `share_ptr` will also free the same
- // space again when this constructor completed. It will cause
- // `free(): double free detected` or `free(): invalid pointer` error.
- SystemdTimestamp times;
- std::array<std::pair<std::string, uint64_t*>, 6> bootTimestamp = {
- std::make_pair( // Firmware
- std::string(kSystemdFirmwareTime), ×.firmware),
- std::make_pair( // Loader
- std::string(kSystemdLoaderTime), ×.loader),
- std::make_pair( // Kernel
- std::string(kSystemdKernelTime), ×.kernel),
- std::make_pair( // InitRD
- std::string(kSystemdInitRDTime), ×.initRD),
- std::make_pair( // Userspace
- std::string(kSystemdUserspaceTime), ×.userspace),
- std::make_pair( // Finish
- std::string(kSystemdFinishTime), ×.finish)};
-
- for (const auto& timestamp : bootTimestamp)
- {
- auto method = conn->new_method_call(
- "org.freedesktop.systemd1", // Systemd Service
- "/org/freedesktop/systemd1", // Systemd Path
- "org.freedesktop.DBus.Properties", // Systemd Iface
- "Get"); // Systemd Func
- method.append("org.freedesktop.systemd1.Manager",
- std::string(timestamp.first));
- std::variant<uint64_t> result;
- try
- {
- conn->call(method).read(result);
- }
- catch (const sdbusplus::exception::SdBusError& e)
+ // If the system is booted, ensure any pending reboot state is cleared.
+ if (mApi->IsNodeRebooting(mNode))
{
fmt::print(
stderr,
- "[CheckBmcFinish] Can't get systemd property {}. ERROR={}\n",
- std::string(timestamp.first), e.what());
- // Restart the timer to keep polling the APML_ALERT status
- mBMCFinishTimer.expires_after(kCheckBmcFinishInterval);
- mBMCFinishTimer.async_wait(
- [this, &conn](const boost::system::error_code& ec) {
- CheckBmcFinish(ec, conn);
- });
+ "System already booted; marking reboot as complete for '{}'\n",
+ mNode.node_name);
+ btm::log::LogIfError(mApi->NotifyNodeComplete(mNode));
}
- *timestamp.second = std::get<uint64_t>(result);
+ else
+ {
+ fmt::print(stderr, "System already booted. No action needed.\n");
+ }
+ return;
}
- // This daemon may start before the userspace is fully ready. So we need
- // to confirm if userspace is fully ready by checking `times.finish`
- // equals zero or not.
- if (times.finish == 0)
+ // If not booted, start polling for boot completion.
+ fmt::print(stderr,
+ "System not yet booted. Waiting for systemd to finish...\n");
+ mBMCFinishTimer.expires_at(std::chrono::steady_clock::now());
+ mBMCFinishTimer.async_wait(
+ [this](const auto& ec) { UpdateBmcCheckpoints(ec); });
+}
+
+std::optional<uint64_t>
+ Handler::QuerySystemdTimestamp(std::string_view propertyName)
+{
+ auto method = mDbusConn->new_method_call(
+ "org.freedesktop.systemd1", // Systemd Service
+ "/org/freedesktop/systemd1", // Systemd Path
+ "org.freedesktop.DBus.Properties", // Systemd Iface
+ "Get"); // Systemd Func
+ method.append("org.freedesktop.systemd1.Manager", propertyName);
+
+ try
{
- fmt::print(
- stderr,
- "[CheckBmcFinish] `FinishTimestampMonotonic` is not ready yet\n");
- mBMCFinishTimer.expires_after(kCheckBmcFinishInterval);
- mBMCFinishTimer.async_wait(
- [this, &conn](const boost::system::error_code& ec) {
- CheckBmcFinish(ec, conn);
- });
+ auto reply = mDbusConn->call(method);
+ std::variant<uint64_t> result;
+ reply.read(result);
+ return std::get<uint64_t>(result);
+ }
+ catch (const sdbusplus::exception::SdBusError& e)
+ {
+ fmt::print(stderr, "Failed to get systemd property '{}': {}\n",
+ propertyName, e.what());
+ return std::nullopt;
+ }
+}
+
+void Handler::RestartPolling()
+{
+ mBMCFinishTimer.expires_after(kCheckBmcFinishInterval);
+ mBMCFinishTimer.async_wait(
+ [this](const auto& ec) { UpdateBmcCheckpoints(ec); });
+}
+
+void Handler::UpdateBmcCheckpoints(const boost::system::error_code& ec)
+{
+ if (ec)
+ {
+ if (ec != boost::asio::error::operation_aborted)
+ {
+ fmt::print(stderr, "BMC checkpoint timer error: {}\n",
+ ec.message());
+ }
+ return;
}
- absl::Status status;
- SystemdDuration durations = CalculateSystemdDuration(times);
- status = mApi->SetNodesDurationByTag(
- btm::kBootTimeTagBMC, convertName(kSystemdFirmwareTime),
- durations.firmware / kMillisecondPerSecond);
- btm::log::LogIfError(status);
- status = mApi->SetNodesDurationByTag(
- btm::kBootTimeTagBMC, convertName(kSystemdLoaderTime),
- durations.loader / kMillisecondPerSecond);
- btm::log::LogIfError(status);
- status = mApi->SetNodesDurationByTag(
- btm::kBootTimeTagBMC, convertName(kSystemdKernelTime),
- durations.kernel / kMillisecondPerSecond);
- btm::log::LogIfError(status);
- status = mApi->SetNodesDurationByTag(
- btm::kBootTimeTagBMC, convertName(kSystemdInitRDTime),
- durations.initRD / kMillisecondPerSecond);
- btm::log::LogIfError(status);
- status = mApi->SetNodesDurationByTag(
- btm::kBootTimeTagBMC, convertName(kSystemdUserspaceTime),
- durations.userspace / kMillisecondPerSecond);
- btm::log::LogIfError(status);
+ // 1. Check if systemd has finished booting. If not, poll again.
+ std::optional<uint64_t> finishTimestamp =
+ QuerySystemdTimestamp(kSystemdFinishTime);
+ if (!finishTimestamp || *finishTimestamp == 0)
+ {
+ RestartPolling();
+ return;
+ }
+
+ // 2. Systemd is ready. Query all other timestamps.
+ SystemdTimestamps times;
+ times.finish = *finishTimestamp;
+
+ auto queryAndAssign = [&](const std::string_view name,
+ uint64_t& destination) -> bool {
+ if (auto val = QuerySystemdTimestamp(name))
+ {
+ destination = *val;
+ return true;
+ }
+ return false;
+ };
+ if (!queryAndAssign(kSystemdFirmwareTime, times.firmware))
+ {
+ RestartPolling();
+ return;
+ }
+ if (!queryAndAssign(kSystemdLoaderTime, times.loader))
+ {
+ RestartPolling();
+ return;
+ }
+ if (!queryAndAssign(kSystemdKernelTime, times.kernel))
+ {
+ RestartPolling();
+ return;
+ }
+ if (!queryAndAssign(kSystemdInitRDTime, times.initRD))
+ {
+ RestartPolling();
+ return;
+ }
+ if (!queryAndAssign(kSystemdUserspaceTime, times.userspace))
+ {
+ RestartPolling();
+ return;
+ }
+
+ fmt::print(stderr, "Successfully collected all systemd boot timestamps.\n");
+
+ // 3. All data is collected. Calculate and report the durations.
+ SystemdDurations durationMap = CalculateSystemdDuration(times);
#ifdef NPCM7XX_OR_NEWER
// NPCM7XX or newer Nuvoton BMC has a register that starts counting from
// SoC power on. Also uptime starts counting when kernel is up. Thus we
// can get (Firmware + Loader) time by `value[SEC_CNT_ADDR] - uptime`.
constexpr uint32_t SEC_CNT_ADDR = 0xF0801068;
-
- auto powerOnSec = readMem4Bytes(SEC_CNT_ADDR);
- auto upTimeMS = getUpTimeInMs();
- if (powerOnSec != std::nullopt && upTimeMS != std::nullopt)
+ if (auto powerOnSec = readMem4Bytes(SEC_CNT_ADDR); powerOnSec)
{
- status = mApi->SetNodesDurationByTag(
- btm::kBootTimeTagBMC, "FirmwarePlusLoader",
- powerOnSec.value() * 1000 - upTimeMS.value());
- btm::log::LogIfError(status);
+ if (auto upTimeMS = getUpTimeInMs(); upTimeMS)
+ {
+ // This register provides a more accurate power-on to kernel-up
+ // time.
+ durationMap.firmware = (powerOnSec.value() * 1000) -
+ upTimeMS.value();
+ durationMap.loader = 0; // The combined time is stored in firmware.
+ }
}
#endif
-// BMC marks the boot process as `completed` automatically if we do *NOT* have
-// external daemon to do so.
-#ifdef AUTO_BMC_COMPLETE
- status = mApi->SetNodesCheckpointByTag(btm::kBootTimeTagBMC, "UserspaceEnd",
- 0, 0);
- btm::log::LogIfError(status);
- status = mApi->NotifyNodesCompleteByTag(btm::kBootTimeTagBMC);
- btm::log::LogIfError(status);
-#endif
+ // 4. Report the calculated durations.
+ btm::log::LogIfError(mApi->SetNodeDuration(
+ mNode, GetStageName(kSystemdFirmwareTime), durationMap.firmware));
+ btm::log::LogIfError(mApi->SetNodeDuration(
+ mNode, GetStageName(kSystemdLoaderTime), durationMap.loader));
+ btm::log::LogIfError(mApi->SetNodeDuration(
+ mNode, GetStageName(kSystemdKernelTime), durationMap.kernel));
+ btm::log::LogIfError(mApi->SetNodeDuration(
+ mNode, GetStageName(kSystemdInitRDTime), durationMap.initRD));
+ btm::log::LogIfError(mApi->SetNodeDuration(
+ mNode, GetStageName(kSystemdUserspaceTime), durationMap.userspace));
+
+ // 5. Finalize the boot process.
+ btm::log::LogIfError(mApi->SetNodeCheckpoint(mNode, "UserspaceEnd", 0, 0));
+ btm::log::LogIfError(mApi->NotifyNodeComplete(mNode));
}
#ifdef NPCM7XX_OR_NEWER
@@ -273,8 +299,8 @@
}
catch (const std::exception& e)
{
- fmt::print(stderr, "[{}]: Throw exception: %s\n", __FUNCTION__,
- e.what());
+ fmt::print(stderr, "Error reading /dev/mem at address {:#x}: {}\n",
+ target, e.what());
return std::nullopt;
}
@@ -284,19 +310,23 @@
std::optional<int64_t> Handler::getUpTimeInMs()
{
- constexpr int32_t kMillisecondPerSecond = 1000;
std::ifstream fin("/proc/uptime");
if (!fin.is_open())
{
- fmt::print(stderr, "[{}]: Can not read \"/proc/uptime\"\n",
- __FUNCTION__);
+ fmt::print(stderr,
+ "Failed to open /proc/uptime to read system uptime.\n");
return std::nullopt;
}
- double uptimeSec;
+ double uptimeSec = 0.0;
fin >> uptimeSec;
- fin.close();
+ if (fin.fail())
+ {
+ fmt::print(stderr,
+ "Failed to parse system uptime from /proc/uptime.\n");
+ return std::nullopt;
+ }
- return static_cast<int64_t>(uptimeSec * kMillisecondPerSecond);
+ return static_cast<int64_t>(uptimeSec * 1000);
}
#endif // NPCM7XX_OR_NEWER
