diff --git a/include/spdlog/spdlog.h b/include/spdlog/spdlog.h index 5da20621..94f9c6e1 100644 --- a/include/spdlog/spdlog.h +++ b/include/spdlog/spdlog.h @@ -151,6 +151,48 @@ void drop(const std::string &name); void drop_all(); +/////////////////////////////////////////////////////////////////////////////// +// Lower cost run-time logging macros +// This elminates any function calls or argument passing if the log level +// is below required level for logging and only incurs an inplace if check +// +// Example: +// spdlog::set_level(spdlog::level::info); +// CustomClassWithStreamOverloaded obj(); +// SPDLOG_PERF_TRACE(logger, "custom class with operator<<: {}..{}", obj, val); +// +// Duration calculations on Visual Studio 2017 64-bit Release build: +// +// Run tests/perf_log_macro.cpp +// with #define PERF_LOG_MACRO_PRINT_DURATIONS uncommented for results on your platform +// +// Number of logs: 1000 +// Log level requires writing using PERF runtime macro:1969us +// Log level requires writing using NORMAL interface: 1917us +// +// Number of logs: 10000 +// Log level does NOT require writing using PERF runtime macro: 6us +// Log level does NOT require writing using NORMAL interface: 62us +/////////////////////////////////////////////////////////////////////////////// +#define SPDLOG_PERF_LOG(logger, flag, level, ...) \ + if (flag && logger->should_log(level)) \ + { \ + logger->log(level, __VA_ARGS__); \ + } + +#define SPDLOG_PERF_TRACE(logger, ...) SPDLOG_PERF_LOG(logger.get(), true, spdlog::level::trace, __VA_ARGS__) +#define SPDLOG_PERF_TRACE_IF(logger, flag, ...) SPDLOG_PERF_LOG(logger.get(), flag, spdlog::level::trace, __VA_ARGS__) +#define SPDLOG_PERF_DEBUG(logger, ...) SPDLOG_PERF_LOG(logger.get(), true, spdlog::level::debug, __VA_ARGS__) +#define SPDLOG_PERF_DEBUG_IF(logger, flag, ...) SPDLOG_PERF_LOG(logger.get(), flag, spdlog::level::debug, __VA_ARGS__) +#define SPDLOG_PERF_INFO(logger, ...) SPDLOG_PERF_LOG(logger.get(), true, spdlog::level::info, __VA_ARGS__) +#define SPDLOG_PERF_INFO_IF(logger, flag, ...) SPDLOG_PERF_LOG(logger.get(), flag, spdlog::level::info, __VA_ARGS__) +#define SPDLOG_PERF_WARN(logger, ...) SPDLOG_PERF_LOG(logger.get(), true, spdlog::level::warn, __VA_ARGS__) +#define SPDLOG_PERF_WARN_IF(logger, flag, ...) SPDLOG_PERF_LOG(logger.get(), flag, spdlog::level::warn, __VA_ARGS__) +#define SPDLOG_PERF_ERR(logger, ...) SPDLOG_PERF_LOG(logger.get(), true, spdlog::level::err, __VA_ARGS__) +#define SPDLOG_PERF_ERR_IF(logger, flag, ...) SPDLOG_PERF_LOG(logger.get(), flag, spdlog::level::err, __VA_ARGS__) +#define SPDLOG_PERF_CRITICAL(logger, ...) SPDLOG_PERF_LOG(logger.get(), true, spdlog::level::critical, __VA_ARGS__) +#define SPDLOG_PERF_CRITICAL_IF(logger, flag, ...) SPDLOG_PERF_LOG(logger.get(), flag, spdlog::level::critical, __VA_ARGS__) + /////////////////////////////////////////////////////////////////////////////// // // Trace & Debug can be switched on/off at compile time for zero cost debug statements. diff --git a/tests/perf_log_macro.cpp b/tests/perf_log_macro.cpp new file mode 100644 index 00000000..f86220a6 --- /dev/null +++ b/tests/perf_log_macro.cpp @@ -0,0 +1,128 @@ + +#include +#include +#include +#include +#include "includes.h" +#include + +// Uncomment below to see timing calculations printed to stdout +//#define PERF_LOG_MACRO_PRINT_DURATIONS + +struct MyObj +{ + MyObj() + : val(0) + , a_long_string("AAAAAAAAAAAAAAAAAAAAAAAAAABBBBBBBBBBBBBBBBBBBBBBBBCCCCCCCCCCCCCCCCCCCCCCCCCCCCCC") + , stream_run(false) + {} + int val; + std::string a_long_string; + mutable bool stream_run; +}; +std::ostream& operator<<(std::ostream& os, const MyObj& c) +{ + c.stream_run = true; + return os << c.a_long_string << " a " << c.val; +} + +TEST_CASE("PERF log macro does not run the ostream", "[PERF_log_macro]") +{ + MyObj obj; + auto null_sink = std::make_shared(); + auto logger = std::make_shared("null_logger", null_sink); + logger->set_level(spdlog::level::info); + SPDLOG_PERF_TRACE(logger, "another obj, {}", obj); + logger->set_level(spdlog::level::trace); + CHECK(!obj.stream_run); + SPDLOG_PERF_TRACE(logger, "another obj, {}", obj); + CHECK(obj.stream_run); +} + +TEST_CASE("performace test when writing suing macro", "[PERF_log_macro]") +{ + { + MyObj obj; + auto null_sink = std::make_shared(); + auto logger = std::make_shared("null_logger", null_sink); + logger->set_level(spdlog::level::info); + + std::size_t loop_count = 1000; + auto begin = std::chrono::high_resolution_clock::now(); + for (size_t i = 0; i < loop_count; i++) + { + SPDLOG_PERF_INFO(logger, "custom class with operator<<: {}..", obj); + } + auto end = std::chrono::high_resolution_clock::now(); + auto dur = end - begin; + auto seconds = std::chrono::duration_cast(dur).count(); +#if defined(PERF_LOG_MACRO_PRINT_DURATIONS) + std::cout << "Log level requires writing using PERF runtime macro:" << seconds << "us" << std::endl; +#endif + } +} +TEST_CASE("performace test when writing", "[PERF_log_macro]") +{ + MyObj obj; + auto null_sink = std::make_shared(); + auto logger = std::make_shared("null_logger", null_sink); + logger->set_level(spdlog::level::info); + + std::size_t loop_count = 1000; + { + auto begin = std::chrono::high_resolution_clock::now(); + for (size_t i = 0; i < loop_count; i++) + { + logger->info("custom class with operator<<: {}..", obj); + } + auto end = std::chrono::high_resolution_clock::now(); + auto dur = end - begin; + auto seconds = std::chrono::duration_cast(dur).count(); +#if defined(PERF_LOG_MACRO_PRINT_DURATIONS) + std::cout << "Log level requires writing using NORMAL interface: " << seconds << "us" << std::endl; +#endif + } +} + + +TEST_CASE("performace test not writing", "[PERF_log_macro]") +{ + MyObj obj; + auto null_sink = std::make_shared(); + auto logger = std::make_shared("null_logger", null_sink); + logger->set_level(spdlog::level::info); + + std::size_t loop_count = 10000; + { + auto begin = std::chrono::high_resolution_clock::now(); + for (size_t i = 0; i < loop_count; i++) + { + SPDLOG_PERF_TRACE(logger, "custom class with operator<<: {}..{}", obj, 1234); + } + auto end = std::chrono::high_resolution_clock::now(); + auto dur = end - begin; + auto seconds = std::chrono::duration_cast(dur).count(); +#if defined(PERF_LOG_MACRO_PRINT_DURATIONS) + std::cout << "Log level does NOT require writing using PERF runtime macro: " << seconds << "us" << std::endl; +#endif + } + { + auto begin = std::chrono::high_resolution_clock::now(); + for (size_t i = 0; i < loop_count; i++) + { + logger->trace("custom class with operator<<: {}..{}", obj, 1234); + } + auto end = std::chrono::high_resolution_clock::now(); + auto dur = end - begin; + auto seconds = std::chrono::duration_cast(dur).count(); +#if defined(PERF_LOG_MACRO_PRINT_DURATIONS) + std::cout << "Log level does NOT require writing using NORMAL interface: " << seconds << "us" << std::endl; +#endif + } +} + + + + + +