performance: trace how much time is spent in sysrepo interactions
I did not want to mess with passing a custom logger, so we now have a
default one (the "main" one, obviously). I'm very much tempted to get
rid of all the custom logging, TBH, but that's for some other time.
The explicit flush is there to avoid lost performance data on (some)
exceptions.
Change-Id: I7d0a4d79e4777f77544ad0f39af8ce58de2c31a6
diff --git a/CMakeLists.txt b/CMakeLists.txt
index 05c7a92..e0b0108 100644
--- a/CMakeLists.txt
+++ b/CMakeLists.txt
@@ -90,6 +90,8 @@
add_library(velia-utils STATIC
src/utils/alarms.cpp
src/utils/alarms.h
+ src/utils/benchmark.cpp
+ src/utils/benchmark.h
src/utils/exceptions.cpp
src/utils/exceptions.h
src/utils/exec.cpp
diff --git a/src/ietf-hardware/sysrepo/Sysrepo.cpp b/src/ietf-hardware/sysrepo/Sysrepo.cpp
index cd1af13..938350e 100644
--- a/src/ietf-hardware/sysrepo/Sysrepo.cpp
+++ b/src/ietf-hardware/sysrepo/Sysrepo.cpp
@@ -10,6 +10,7 @@
#include <sysrepo-cpp/Connection.hpp>
#include "Sysrepo.h"
#include "utils/alarms.h"
+#include "utils/benchmark.h"
#include "utils/log.h"
#include "utils/sysrepo.h"
@@ -106,6 +107,7 @@
});
while (!m_quit) {
+ auto benchmark = std::make_optional<velia::utils::MeasureTime>("ietf-hardware/poll");
m_log->trace("IetfHardware poll");
auto [hwStateValues, thresholds, activeSensors, sideLoadedAlarms] = m_hwState->process();
@@ -232,6 +234,7 @@
}
prevValues = std::move(hwStateValues);
+ benchmark.reset();
std::this_thread::sleep_for(m_pollInterval);
}
});
diff --git a/src/utils/alarms.cpp b/src/utils/alarms.cpp
index 2dee0bf..280004b 100644
--- a/src/utils/alarms.cpp
+++ b/src/utils/alarms.cpp
@@ -7,6 +7,7 @@
#include <sysrepo-cpp/Enum.hpp>
#include <spdlog/spdlog.h>
#include "alarms.h"
+#include "utils/benchmark.h"
#include "utils/libyang.h"
#include "utils/sysrepo.h"
@@ -20,6 +21,7 @@
namespace velia::alarms {
void push(sysrepo::Session session, const std::string& alarmId, const std::string& resource, const std::string& severity, const std::string& text)
{
+ WITH_TIME_MEASUREMENT{};
auto inputNode = session.getContext().newPath(alarmRpc, std::nullopt);
inputNode.newPath(alarmRpc + "/resource"s, resource);
@@ -34,6 +36,7 @@
void pushInventory(sysrepo::Session session, const std::vector<AlarmInventoryEntry>& entries)
{
+ WITH_TIME_MEASUREMENT{};
utils::ScopedDatastoreSwitch s(session, sysrepo::Datastore::Operational);
for (const auto& entry: entries) {
@@ -52,11 +55,13 @@
}
spdlog::get("main")->trace("alarms::pushInventory: {}", *session.getPendingChanges()->printStr(libyang::DataFormat::JSON, libyang::PrintFlags::WithSiblings));
+ WITH_TIME_MEASUREMENT{"pushInventory/applyChanges"};
session.applyChanges();
}
void addResourcesToInventory(sysrepo::Session session, const std::map<std::string, std::vector<std::string>>& resourcesPerAlarm)
{
+ WITH_TIME_MEASUREMENT{};
utils::ScopedDatastoreSwitch s(session, sysrepo::Datastore::Operational);
for (const auto& [alarmId, resources] : resourcesPerAlarm) {
@@ -67,6 +72,7 @@
}
}
spdlog::get("main")->trace("alarms::addResourcesToInventory: {}", *session.getPendingChanges()->printStr(libyang::DataFormat::JSON, libyang::PrintFlags::WithSiblings));
+ WITH_TIME_MEASUREMENT{"addResourcesToInventory/applyChanges"};
session.applyChanges();
}
diff --git a/src/utils/benchmark.cpp b/src/utils/benchmark.cpp
new file mode 100644
index 0000000..0269a0a
--- /dev/null
+++ b/src/utils/benchmark.cpp
@@ -0,0 +1,40 @@
+/*
+ * Copyright (C) 2024 CESNET, https://photonics.cesnet.cz/
+ *
+ * Written by Jan Kundrát <jan.kundrat@cesnet.cz>
+*/
+
+#include "benchmark.h"
+#include <fmt/format.h>
+#include <spdlog/spdlog.h>
+
+using namespace std::literals;
+
+namespace velia::utils {
+ MeasureTime::MeasureTime(const std::source_location location)
+ : start(std::chrono::steady_clock::now())
+ , what(location.function_name())
+{
+ if (auto fn = location.function_name(); fn != ""sv) {
+ what = fn;
+ } else {
+ what = fmt::format("{}:{}:{}", location.file_name(), location.line(), location.column());
+ }
+}
+
+MeasureTime::MeasureTime(const std::string_view message)
+ : start(std::chrono::steady_clock::now())
+ , what(message)
+{
+}
+
+MeasureTime::~MeasureTime()
+{
+ auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::steady_clock::now() - start).count();
+ if (ms > 1'000) {
+ spdlog::warn("[PERFORMANCE][TOO_SLOW] {} {}ms", what, ms);
+ } else {
+ spdlog::trace("[PERFORMANCE]: {} {}ms", what, ms);
+ }
+}
+}
diff --git a/src/utils/benchmark.h b/src/utils/benchmark.h
new file mode 100644
index 0000000..b394120
--- /dev/null
+++ b/src/utils/benchmark.h
@@ -0,0 +1,26 @@
+/*
+ * Copyright (C) 2024 CESNET, https://photonics.cesnet.cz/
+ *
+ * Written by Jan Kundrát <jan.kundrat@cesnet.cz>
+*/
+
+#pragma once
+
+#include <chrono>
+#include <string_view>
+#include <source_location>
+
+namespace velia::utils {
+/** @short Log profiling information about how much time was spent in a given block */
+class MeasureTime {
+ std::chrono::time_point<std::chrono::steady_clock> start;
+ std::string what;
+public:
+ MeasureTime(const std::source_location location = std::source_location::current());
+ MeasureTime(const std::string_view message);
+ ~MeasureTime();
+};
+}
+#define VELIA_UTILS_PASTE_INNER(X, Y) X##Y
+#define VELIA_UTILS_PASTE(X, Y) VELIA_UTILS_PASTE_INNER(X, Y)
+#define WITH_TIME_MEASUREMENT ::velia::utils::MeasureTime VELIA_UTILS_PASTE(_benchmark_, __LINE__)
diff --git a/src/utils/log-init.cpp b/src/utils/log-init.cpp
index 0b2f6cf..2493052 100644
--- a/src/utils/log-init.cpp
+++ b/src/utils/log-init.cpp
@@ -20,5 +20,6 @@
for (const auto& name : {"main", "health", "hardware", "sysrepo", "system", "firewall"}) {
spdlog::register_logger(std::make_shared<spdlog::logger>(name, sink));
}
+ spdlog::set_default_logger(spdlog::get("main"));
}
}
diff --git a/src/utils/sysrepo.cpp b/src/utils/sysrepo.cpp
index 188f6a6..008c556 100644
--- a/src/utils/sysrepo.cpp
+++ b/src/utils/sysrepo.cpp
@@ -7,6 +7,7 @@
*/
#include "sysrepo.h"
+#include "utils/benchmark.h"
#include "utils/log.h"
extern "C" {
@@ -118,6 +119,7 @@
/** @brief Set or remove paths in Sysrepo's current datastore. */
void valuesPush(const std::map<std::string, std::string>& values, const std::vector<std::string>& removePaths, const std::vector<std::string>& discardPaths, ::sysrepo::Session session)
{
+ WITH_TIME_MEASUREMENT{};
if (values.empty() && removePaths.empty() && discardPaths.empty()) return;
std::optional<libyang::DataNode> edit;
@@ -126,6 +128,7 @@
if (edit) {
session.editBatch(*edit, sysrepo::DefaultOperation::Merge);
spdlog::get("main")->trace("valuesPush: {}", *session.getPendingChanges()->printStr(libyang::DataFormat::JSON, libyang::PrintFlags::WithSiblings));
+ WITH_TIME_MEASUREMENT("valuesPush<map>/applyChanges");
session.applyChanges();
}
}
@@ -140,6 +143,7 @@
/** @brief Set or remove paths in Sysrepo's current datastore. */
void valuesPush(const std::vector<YANGPair>& values, const std::vector<std::string>& removePaths, const std::vector<std::string>& discardPaths, sysrepo::Session session)
{
+ WITH_TIME_MEASUREMENT{};
if (values.empty() && removePaths.empty() && discardPaths.empty())
return;
@@ -149,6 +153,7 @@
if (edit) {
session.editBatch(*edit, sysrepo::DefaultOperation::Merge);
spdlog::get("main")->trace("valuesPush: {}", *session.getPendingChanges()->printStr(libyang::DataFormat::JSON, libyang::PrintFlags::WithSiblings));
+ WITH_TIME_MEASUREMENT("valuesPush<vector>/applyChanges");
session.applyChanges();
}
}