From 4c64711fc9038b21b737b320c28925968c61dc54 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Mon, 15 Sep 2025 18:34:22 +0300 Subject: [PATCH] test(compiled-level): cover scope timer macros --- examples/example_logit_basic.cpp | 14 ++ include/logit_cpp/LogIt.hpp | 1 + include/logit_cpp/logit/LogMacros.hpp | 141 ++++++++++++++++++ include/logit_cpp/logit/detail/ScopeTimer.hpp | 69 +++++++++ tests/compiled_level_test.cpp | 8 + tests/fmt_macros_test.cpp | 8 +- 6 files changed, 240 insertions(+), 1 deletion(-) create mode 100644 include/logit_cpp/logit/detail/ScopeTimer.hpp diff --git a/examples/example_logit_basic.cpp b/examples/example_logit_basic.cpp index 291a9f4..fbb92df 100644 --- a/examples/example_logit_basic.cpp +++ b/examples/example_logit_basic.cpp @@ -85,6 +85,20 @@ int main() { std::string email = "user@example.com"; LOGIT_TRACE(auth_success, email); + { + LOGIT_SCOPE_INFO("load_config"); + std::this_thread::sleep_for(std::chrono::milliseconds(1)); + } + { + LOGIT_SCOPE_INFO_T(10, "heavy_step"); + std::this_thread::sleep_for(std::chrono::milliseconds(11)); + } + { + int step_id = 7; + LOGIT_SCOPE_FMT_INFO("step_{}", step_id); + std::this_thread::sleep_for(std::chrono::milliseconds(1)); + } + // Demonstrate macros for controlling log frequency and tagging for (int i = 0; i < 5; ++i) { LOGIT_TRACE_ONCE("Trace once example"); diff --git a/include/logit_cpp/LogIt.hpp b/include/logit_cpp/LogIt.hpp index 82a1ae8..505365a 100644 --- a/include/logit_cpp/LogIt.hpp +++ b/include/logit_cpp/LogIt.hpp @@ -10,6 +10,7 @@ #include "logit/utils.hpp" #include "logit/Logger.hpp" #include "logit/LogStream.hpp" +#include "logit/detail/ScopeTimer.hpp" #include "logit/LogMacros.hpp" #include "logit/formatter.hpp" #include "logit/loggers.hpp" diff --git a/include/logit_cpp/logit/LogMacros.hpp b/include/logit_cpp/logit/LogMacros.hpp index 1b4f92a..4de9daa 100644 --- a/include/logit_cpp/logit/LogMacros.hpp +++ b/include/logit_cpp/logit/LogMacros.hpp @@ -115,6 +115,147 @@ static_assert(LOGIT_LEVEL_FATAL == static_cast(logit::LogLevel::LOG_LVL_FAT /// \} +//------------------------------------------------------------------------------ +// Scope-based timing macros + +/// \name Scope-Based Timing +/// RAII timers that log the duration of a scope. +/// \{ + +#define LOGIT_DETAIL_SCOPE(level, phase) \ + ::logit::detail::ScopeTimer LOGIT_CONCAT(_logit_scope_, __COUNTER__)(level, (phase), __FILE__, __LINE__, LOGIT_FUNCTION, -1, 0) + +#define LOGIT_DETAIL_SCOPE_T(level, threshold_ms, phase) \ + ::logit::detail::ScopeTimer LOGIT_CONCAT(_logit_scope_, __COUNTER__)(level, (phase), __FILE__, __LINE__, LOGIT_FUNCTION, -1, (threshold_ms)) + +#ifdef LOGIT_WITH_FMT +#define LOGIT_DETAIL_SCOPE_FMT(level, fmt_str, ...) \ + ::logit::detail::ScopeTimer LOGIT_CONCAT(_logit_scope_, __COUNTER__)(level, fmt::format(fmt_str, __VA_ARGS__), __FILE__, __LINE__, LOGIT_FUNCTION, -1, 0) +#define LOGIT_DETAIL_SCOPE_FMT_T(level, threshold_ms, fmt_str, ...) \ + ::logit::detail::ScopeTimer LOGIT_CONCAT(_logit_scope_, __COUNTER__)(level, fmt::format(fmt_str, __VA_ARGS__), __FILE__, __LINE__, LOGIT_FUNCTION, -1, (threshold_ms)) +#else +#define LOGIT_DETAIL_SCOPE_FMT(level, fmt_str, ...) \ + ::logit::detail::ScopeTimer LOGIT_CONCAT(_logit_scope_, __COUNTER__)(level, logit::format(fmt_str, __VA_ARGS__), __FILE__, __LINE__, LOGIT_FUNCTION, -1, 0) +#define LOGIT_DETAIL_SCOPE_FMT_T(level, threshold_ms, fmt_str, ...) \ + ::logit::detail::ScopeTimer LOGIT_CONCAT(_logit_scope_, __COUNTER__)(level, logit::format(fmt_str, __VA_ARGS__), __FILE__, __LINE__, LOGIT_FUNCTION, -1, (threshold_ms)) +#endif + +#if LOGIT_COMPILED_LEVEL <= LOGIT_LEVEL_TRACE +#define LOGIT_SCOPE_TRACE(phase) LOGIT_DETAIL_SCOPE(::logit::LogLevel::LOG_LVL_TRACE, phase) +#define LOGIT_SCOPE_TRACE_T(threshold_ms, phase) \ + LOGIT_DETAIL_SCOPE_T(::logit::LogLevel::LOG_LVL_TRACE, threshold_ms, phase) +#else +#define LOGIT_SCOPE_TRACE(phase) do { } while (0) +#define LOGIT_SCOPE_TRACE_T(threshold_ms, phase) do { } while (0) +#endif + +#if LOGIT_COMPILED_LEVEL <= LOGIT_LEVEL_DEBUG +#define LOGIT_SCOPE_DEBUG(phase) LOGIT_DETAIL_SCOPE(::logit::LogLevel::LOG_LVL_DEBUG, phase) +#define LOGIT_SCOPE_DEBUG_T(threshold_ms, phase) \ + LOGIT_DETAIL_SCOPE_T(::logit::LogLevel::LOG_LVL_DEBUG, threshold_ms, phase) +#else +#define LOGIT_SCOPE_DEBUG(phase) do { } while (0) +#define LOGIT_SCOPE_DEBUG_T(threshold_ms, phase) do { } while (0) +#endif + +#if LOGIT_COMPILED_LEVEL <= LOGIT_LEVEL_INFO +#define LOGIT_SCOPE_INFO(phase) LOGIT_DETAIL_SCOPE(::logit::LogLevel::LOG_LVL_INFO, phase) +#define LOGIT_SCOPE_INFO_T(threshold_ms, phase) \ + LOGIT_DETAIL_SCOPE_T(::logit::LogLevel::LOG_LVL_INFO, threshold_ms, phase) +#else +#define LOGIT_SCOPE_INFO(phase) do { } while (0) +#define LOGIT_SCOPE_INFO_T(threshold_ms, phase) do { } while (0) +#endif + +#if LOGIT_COMPILED_LEVEL <= LOGIT_LEVEL_WARN +#define LOGIT_SCOPE_WARN(phase) LOGIT_DETAIL_SCOPE(::logit::LogLevel::LOG_LVL_WARN, phase) +#define LOGIT_SCOPE_WARN_T(threshold_ms, phase) \ + LOGIT_DETAIL_SCOPE_T(::logit::LogLevel::LOG_LVL_WARN, threshold_ms, phase) +#else +#define LOGIT_SCOPE_WARN(phase) do { } while (0) +#define LOGIT_SCOPE_WARN_T(threshold_ms, phase) do { } while (0) +#endif + +#if LOGIT_COMPILED_LEVEL <= LOGIT_LEVEL_ERROR +#define LOGIT_SCOPE_ERROR(phase) LOGIT_DETAIL_SCOPE(::logit::LogLevel::LOG_LVL_ERROR, phase) +#define LOGIT_SCOPE_ERROR_T(threshold_ms, phase) \ + LOGIT_DETAIL_SCOPE_T(::logit::LogLevel::LOG_LVL_ERROR, threshold_ms, phase) +#else +#define LOGIT_SCOPE_ERROR(phase) do { } while (0) +#define LOGIT_SCOPE_ERROR_T(threshold_ms, phase) do { } while (0) +#endif + +#if LOGIT_COMPILED_LEVEL <= LOGIT_LEVEL_FATAL +#define LOGIT_SCOPE_FATAL(phase) LOGIT_DETAIL_SCOPE(::logit::LogLevel::LOG_LVL_FATAL, phase) +#define LOGIT_SCOPE_FATAL_T(threshold_ms, phase) \ + LOGIT_DETAIL_SCOPE_T(::logit::LogLevel::LOG_LVL_FATAL, threshold_ms, phase) +#else +#define LOGIT_SCOPE_FATAL(phase) do { } while (0) +#define LOGIT_SCOPE_FATAL_T(threshold_ms, phase) do { } while (0) +#endif + +#if LOGIT_COMPILED_LEVEL <= LOGIT_LEVEL_TRACE +#define LOGIT_SCOPE_FMT_TRACE(fmt_str, ...) \ + LOGIT_DETAIL_SCOPE_FMT(::logit::LogLevel::LOG_LVL_TRACE, fmt_str, __VA_ARGS__) +#define LOGIT_SCOPE_FMT_TRACE_T(threshold_ms, fmt_str, ...) \ + LOGIT_DETAIL_SCOPE_FMT_T(::logit::LogLevel::LOG_LVL_TRACE, threshold_ms, fmt_str, __VA_ARGS__) +#else +#define LOGIT_SCOPE_FMT_TRACE(fmt_str, ...) do { } while (0) +#define LOGIT_SCOPE_FMT_TRACE_T(threshold_ms, fmt_str, ...) do { } while (0) +#endif + +#if LOGIT_COMPILED_LEVEL <= LOGIT_LEVEL_DEBUG +#define LOGIT_SCOPE_FMT_DEBUG(fmt_str, ...) \ + LOGIT_DETAIL_SCOPE_FMT(::logit::LogLevel::LOG_LVL_DEBUG, fmt_str, __VA_ARGS__) +#define LOGIT_SCOPE_FMT_DEBUG_T(threshold_ms, fmt_str, ...) \ + LOGIT_DETAIL_SCOPE_FMT_T(::logit::LogLevel::LOG_LVL_DEBUG, threshold_ms, fmt_str, __VA_ARGS__) +#else +#define LOGIT_SCOPE_FMT_DEBUG(fmt_str, ...) do { } while (0) +#define LOGIT_SCOPE_FMT_DEBUG_T(threshold_ms, fmt_str, ...) do { } while (0) +#endif + +#if LOGIT_COMPILED_LEVEL <= LOGIT_LEVEL_INFO +#define LOGIT_SCOPE_FMT_INFO(fmt_str, ...) \ + LOGIT_DETAIL_SCOPE_FMT(::logit::LogLevel::LOG_LVL_INFO, fmt_str, __VA_ARGS__) +#define LOGIT_SCOPE_FMT_INFO_T(threshold_ms, fmt_str, ...) \ + LOGIT_DETAIL_SCOPE_FMT_T(::logit::LogLevel::LOG_LVL_INFO, threshold_ms, fmt_str, __VA_ARGS__) +#else +#define LOGIT_SCOPE_FMT_INFO(fmt_str, ...) do { } while (0) +#define LOGIT_SCOPE_FMT_INFO_T(threshold_ms, fmt_str, ...) do { } while (0) +#endif + +#if LOGIT_COMPILED_LEVEL <= LOGIT_LEVEL_WARN +#define LOGIT_SCOPE_FMT_WARN(fmt_str, ...) \ + LOGIT_DETAIL_SCOPE_FMT(::logit::LogLevel::LOG_LVL_WARN, fmt_str, __VA_ARGS__) +#define LOGIT_SCOPE_FMT_WARN_T(threshold_ms, fmt_str, ...) \ + LOGIT_DETAIL_SCOPE_FMT_T(::logit::LogLevel::LOG_LVL_WARN, threshold_ms, fmt_str, __VA_ARGS__) +#else +#define LOGIT_SCOPE_FMT_WARN(fmt_str, ...) do { } while (0) +#define LOGIT_SCOPE_FMT_WARN_T(threshold_ms, fmt_str, ...) do { } while (0) +#endif + +#if LOGIT_COMPILED_LEVEL <= LOGIT_LEVEL_ERROR +#define LOGIT_SCOPE_FMT_ERROR(fmt_str, ...) \ + LOGIT_DETAIL_SCOPE_FMT(::logit::LogLevel::LOG_LVL_ERROR, fmt_str, __VA_ARGS__) +#define LOGIT_SCOPE_FMT_ERROR_T(threshold_ms, fmt_str, ...) \ + LOGIT_DETAIL_SCOPE_FMT_T(::logit::LogLevel::LOG_LVL_ERROR, threshold_ms, fmt_str, __VA_ARGS__) +#else +#define LOGIT_SCOPE_FMT_ERROR(fmt_str, ...) do { } while (0) +#define LOGIT_SCOPE_FMT_ERROR_T(threshold_ms, fmt_str, ...) do { } while (0) +#endif + +#if LOGIT_COMPILED_LEVEL <= LOGIT_LEVEL_FATAL +#define LOGIT_SCOPE_FMT_FATAL(fmt_str, ...) \ + LOGIT_DETAIL_SCOPE_FMT(::logit::LogLevel::LOG_LVL_FATAL, fmt_str, __VA_ARGS__) +#define LOGIT_SCOPE_FMT_FATAL_T(threshold_ms, fmt_str, ...) \ + LOGIT_DETAIL_SCOPE_FMT_T(::logit::LogLevel::LOG_LVL_FATAL, threshold_ms, fmt_str, __VA_ARGS__) +#else +#define LOGIT_SCOPE_FMT_FATAL(fmt_str, ...) do { } while (0) +#define LOGIT_SCOPE_FMT_FATAL_T(threshold_ms, fmt_str, ...) do { } while (0) +#endif + +/// \} + //------------------------------------------------------------------------------ // Macros for logging without arguments diff --git a/include/logit_cpp/logit/detail/ScopeTimer.hpp b/include/logit_cpp/logit/detail/ScopeTimer.hpp new file mode 100644 index 0000000..b370777 --- /dev/null +++ b/include/logit_cpp/logit/detail/ScopeTimer.hpp @@ -0,0 +1,69 @@ +#pragma once +#ifndef _LOGIT_DETAIL_SCOPE_TIMER_HPP_INCLUDED +#define _LOGIT_DETAIL_SCOPE_TIMER_HPP_INCLUDED + +/// \file ScopeTimer.hpp +/// \brief RAII timer that logs the duration of a scope. + +#include "../config.hpp" +#include "../utils.hpp" +#include "../Logger.hpp" + +#include +#include + +namespace logit { namespace detail { + + class ScopeTimer { + public: + ScopeTimer(LogLevel level, + std::string phase, + const char* file, + int line, + const char* function, + int logger_index, + int64_t threshold_ms = 0) + : level_(level) + , phase_(std::move(phase)) + , file_(file) + , line_(line) + , function_(function) + , logger_index_(logger_index) + , threshold_ms_(threshold_ms) + , t0_(std::chrono::steady_clock::now()) {} + + ~ScopeTimer() { + const auto t1 = std::chrono::steady_clock::now(); + const auto ms = std::chrono::duration_cast(t1 - t0_).count(); + if (ms < threshold_ms_) return; + + std::string msg = phase_; + msg += " | duration_ms="; + msg += std::to_string(ms); + + Logger::get_instance().log_and_return(LogRecord{ + level_, + LOGIT_WALLCLOCK_MS(), + logit::make_relative(file_, LOGIT_BASE_PATH), + line_, + function_, + std::string(), std::string(), + logger_index_, + false + }, msg); + } + + private: + LogLevel level_; + std::string phase_; + const char* file_; + int line_; + const char* function_; + int logger_index_; + int64_t threshold_ms_; + std::chrono::steady_clock::time_point t0_; + }; + +}} // namespace logit::detail + +#endif // _LOGIT_DETAIL_SCOPE_TIMER_HPP_INCLUDED diff --git a/tests/compiled_level_test.cpp b/tests/compiled_level_test.cpp index 102a865..313dab4 100644 --- a/tests/compiled_level_test.cpp +++ b/tests/compiled_level_test.cpp @@ -39,6 +39,10 @@ int main() { LOGIT_PRINTF_TRACE_IF(false, "%d", should_not_compile()); LOGITF_TRACE_IF(false, "{}", should_not_compile()); LOGIT_FMT_TRACE_IF(false, "{}", should_not_compile()); + LOGIT_SCOPE_TRACE(should_not_compile()); + LOGIT_SCOPE_TRACE_T(0, should_not_compile()); + LOGIT_SCOPE_FMT_TRACE("{}", should_not_compile()); + LOGIT_SCOPE_FMT_TRACE_T(0, "{}", should_not_compile()); // DEBUG macros LOGIT_DEBUG(should_not_compile()); @@ -71,5 +75,9 @@ int main() { LOGIT_PRINTF_DEBUG_IF(false, "%d", should_not_compile()); LOGITF_DEBUG_IF(false, "{}", should_not_compile()); LOGIT_FMT_DEBUG_IF(false, "{}", should_not_compile()); + LOGIT_SCOPE_DEBUG(should_not_compile()); + LOGIT_SCOPE_DEBUG_T(0, should_not_compile()); + LOGIT_SCOPE_FMT_DEBUG("{}", should_not_compile()); + LOGIT_SCOPE_FMT_DEBUG_T(0, "{}", should_not_compile()); return 0; } diff --git a/tests/fmt_macros_test.cpp b/tests/fmt_macros_test.cpp index 164df02..1221ca6 100644 --- a/tests/fmt_macros_test.cpp +++ b/tests/fmt_macros_test.cpp @@ -8,15 +8,21 @@ int main() { LOGITF_INFO("fmt {}", 42); int value = 5; LOGIT_FMT_INFO("{:04}", value); + { + int scope_val = 7; + LOGIT_SCOPE_FMT_INFO("scope {}", scope_val); + } LOGIT_WAIT(); std::ifstream in(LOGIT_GET_LAST_FILE_PATH(0)); std::string line; bool found_fmt = false; bool found_fmt_arg = false; + bool found_scope = false; while (std::getline(in, line)) { if (line.find("fmt 42") != std::string::npos) found_fmt = true; if (line.find("0005") != std::string::npos) found_fmt_arg = true; + if (line.find("scope 7") != std::string::npos) found_scope = true; } LOGIT_SHUTDOWN(); - return (found_fmt && found_fmt_arg) ? 0 : 1; + return (found_fmt && found_fmt_arg && found_scope) ? 0 : 1; }