From 04a8485b17fe5227fbbb99d1384eea2832ef1857 Mon Sep 17 00:00:00 2001 From: gabime Date: Mon, 26 Aug 2019 19:59:16 +0300 Subject: [PATCH] Replaced backtace implementation --- example/example.cpp | 211 +---------------------- include/spdlog/async_logger-inl.h | 17 -- include/spdlog/async_logger.h | 2 - include/spdlog/details/backtracer.h | 45 +++++ include/spdlog/details/thread_pool-inl.h | 18 +- include/spdlog/details/thread_pool.h | 4 +- include/spdlog/logger-inl.h | 56 +++--- include/spdlog/logger.h | 31 +++- include/spdlog/sinks/backtrace_sink.h | 89 ---------- 9 files changed, 104 insertions(+), 369 deletions(-) create mode 100644 include/spdlog/details/backtracer.h delete mode 100644 include/spdlog/sinks/backtrace_sink.h diff --git a/example/example.cpp b/example/example.cpp index c84caef3..1d01b0ae 100644 --- a/example/example.cpp +++ b/example/example.cpp @@ -23,217 +23,12 @@ void clone_example(); int main(int, char *[]) { - spdlog::info("Welcome to spdlog version {}.{}.{} !", SPDLOG_VER_MAJOR, SPDLOG_VER_MINOR, SPDLOG_VER_PATCH); - spdlog::warn("Easy padding in numbers like {:08d}", 12); - spdlog::critical("Support for int: {0:d}; hex: {0:x}; oct: {0:o}; bin: {0:b}", 42); - spdlog::info("Support for floats {:03.2f}", 1.23456); - spdlog::info("Positional args are {1} {0}..", "too", "supported"); - spdlog::info("{:>8} aligned, {:<8} aligned", "right", "left"); - - // Runtime log levels - spdlog::set_level(spdlog::level::info); // Set global log level to info - spdlog::debug("This message should not be displayed!"); - spdlog::set_level(spdlog::level::trace); // Set specific logger's log level - spdlog::debug("This message should be displayed.."); - spdlog::set_level(spdlog::level::info); // Set specific logger's log level - - // Customize msg format for all loggers - spdlog::set_pattern("[%H:%M:%S %z] [%^%L%$] [thread %t] %v"); - spdlog::info("This an info message with custom format"); - spdlog::set_pattern("%+"); // back to default format // Backtrace support of latest debug/trace messages spdlog::enable_backtrace(16); + spdlog::trace("Backtrace message 1"); spdlog::debug("Backtrace message 2"); + spdlog::info("Hello"); spdlog::dump_backtrace(); - - try - { - stdout_logger_example(); - basic_example(); - rotating_example(); - daily_example(); - clone_example(); - async_example(); - binary_example(); - multi_sink_example(); - user_defined_example(); - err_handler_example(); - trace_example(); - - // Flush all *registered* loggers using a worker thread every 3 seconds. - // note: registered loggers *must* be thread safe for this to work correctly! - spdlog::flush_every(std::chrono::seconds(3)); - - // Apply some function on all registered loggers - spdlog::apply_all([&](std::shared_ptr l) { l->info("End of example."); }); - - // Release all spdlog resources, and drop all loggers in the registry. - // This is optional (only mandatory if using windows + async log). - spdlog::shutdown(); - } - - // Exceptions will only be thrown upon failed logger or sink construction (not during logging). - catch (const spdlog::spdlog_ex &ex) - { - std::printf("Log initialization failed: %s\n", ex.what()); - return 1; - } -} - -#include "spdlog/sinks/stdout_color_sinks.h" -// or #include "spdlog/sinks/stdout_sinks.h" if no colors needed. -void stdout_logger_example() -{ - // Create color multi threaded logger. - auto console = spdlog::stdout_color_mt("console"); - // or for stderr: - // auto console = spdlog::stderr_color_mt("error-logger"); -} - -#include "spdlog/sinks/basic_file_sink.h" -void basic_example() -{ - // Create basic file logger (not rotated). - auto my_logger = spdlog::basic_logger_mt("file_logger", "logs/basic-log.txt"); -} - -#include "spdlog/sinks/rotating_file_sink.h" -void rotating_example() -{ - // Create a file rotating logger with 5mb size max and 3 rotated files. - auto rotating_logger = spdlog::rotating_logger_mt("some_logger_name", "logs/rotating.txt", 1048576 * 5, 3); -} - -#include "spdlog/sinks/daily_file_sink.h" -void daily_example() -{ - // Create a daily logger - a new file is created every day on 2:30am. - auto daily_logger = spdlog::daily_logger_mt("daily_logger", "logs/daily.txt", 2, 30); -} - -// Clone a logger and give it new name. -// Useful for creating component/subsystem loggers from some "root" logger. -void clone_example() -{ - auto network_logger = spdlog::default_logger()->clone("network"); - network_logger->info("Logging network stuff.."); -} - -#include "spdlog/async.h" -void async_example() -{ - // Default thread pool settings can be modified *before* creating the async logger: - // spdlog::init_thread_pool(32768, 1); // queue with max 32k items 1 backing thread. - auto async_file = spdlog::basic_logger_mt("async_file_logger", "logs/async_log.txt"); - // alternatively: - // auto async_file = spdlog::create_async("async_file_logger", "logs/async_log.txt"); - - for (int i = 1; i < 101; ++i) - { - async_file->info("Async message #{}", i); - } -} - -// Log binary data as hex. -// Many types of std::container types can be used. -// Iterator ranges are supported too. -// Format flags: -// {:X} - print in uppercase. -// {:s} - don't separate each byte with space. -// {:p} - don't print the position on each line start. -// {:n} - don't split the output to lines. - -#include "spdlog/fmt/bin_to_hex.h" -void binary_example() -{ - std::vector buf; - for (int i = 0; i < 80; i++) - { - buf.push_back(static_cast(i & 0xff)); - } - spdlog::info("Binary example: {}", spdlog::to_hex(buf)); - spdlog::info("Another binary example:{:n}", spdlog::to_hex(std::begin(buf), std::begin(buf) + 10)); - // more examples: - // logger->info("uppercase: {:X}", spdlog::to_hex(buf)); - // logger->info("uppercase, no delimiters: {:Xs}", spdlog::to_hex(buf)); - // logger->info("uppercase, no delimiters, no position info: {:Xsp}", spdlog::to_hex(buf)); -} - -// Compile time log levels. -// define SPDLOG_ACTIVE_LEVEL to required level (e.g. SPDLOG_LEVEL_TRACE) -void trace_example() -{ - // trace from default logger - SPDLOG_TRACE("Some trace message.. {} ,{}", 1, 3.23); - // debug from default logger - SPDLOG_DEBUG("Some debug message.. {} ,{}", 1, 3.23); - - // trace from logger object - auto logger = spdlog::get("file_logger"); - SPDLOG_LOGGER_TRACE(logger, "another trace message"); -} - -// A logger with multiple sinks (stdout and file) - each with a different format and log level. -void multi_sink_example() -{ - auto console_sink = std::make_shared(); - console_sink->set_level(spdlog::level::warn); - console_sink->set_pattern("[multi_sink_example] [%^%l%$] %v"); - - auto file_sink = std::make_shared("logs/multisink.txt", true); - file_sink->set_level(spdlog::level::trace); - - spdlog::logger logger("multi_sink", {console_sink, file_sink}); - logger.set_level(spdlog::level::debug); - logger.warn("this should appear in both console and file"); - logger.info("this message should not appear in the console, only in the file"); -} - -// User defined types logging by implementing operator<< -#include "spdlog/fmt/ostr.h" // must be included -struct my_type -{ - int i; - template - friend OStream &operator<<(OStream &os, const my_type &c) - { - return os << "[my_type i=" << c.i << "]"; - } -}; - -void user_defined_example() -{ - spdlog::info("user defined type: {}", my_type{14}); -} - -// Custom error handler. Will be triggered on log failure. -void err_handler_example() -{ - // can be set globally or per logger(logger->set_error_handler(..)) - spdlog::set_error_handler([](const std::string &msg) { printf("*** Custom log error handler: %s ***\n", msg.c_str()); }); -} - -// syslog example (linux/osx/freebsd) -#ifndef _WIN32 -#include "spdlog/sinks/syslog_sink.h" -void syslog_example() -{ - std::string ident = "spdlog-example"; - auto syslog_logger = spdlog::syslog_logger_mt("syslog", ident, LOG_PID); - syslog_logger->warn("This is warning that will end up in syslog."); -} -#endif - -// Android example. -#if defined(__ANDROID__) -#include "spdlog/sinks/android_sink.h" -void android_example() -{ - std::string tag = "spdlog-android"; - auto android_logger = spdlog::android_logger_mt("android", tag); - android_logger->critical("Use \"adb shell logcat\" to view this message."); -} - -#endif +} \ No newline at end of file diff --git a/include/spdlog/async_logger-inl.h b/include/spdlog/async_logger-inl.h index b0a6fc54..96137921 100644 --- a/include/spdlog/async_logger-inl.h +++ b/include/spdlog/async_logger-inl.h @@ -50,18 +50,6 @@ SPDLOG_INLINE void spdlog::async_logger::flush_() } } -SPDLOG_INLINE void spdlog::async_logger::dump_backtrace_() -{ - if (auto pool_ptr = thread_pool_.lock()) - { - pool_ptr->post_dump_backtrace(shared_from_this(), overflow_policy_); - } - else - { - SPDLOG_THROW(spdlog_ex("async dump_backtrace: thread pool doesn't exist anymore")); - } -} - // // backend functions - called from the thread pool to do the actual job // @@ -90,11 +78,6 @@ SPDLOG_INLINE void spdlog::async_logger::backend_flush_() spdlog::logger::flush_(); } -SPDLOG_INLINE void spdlog::async_logger::backend_dump_backtrace_() -{ - spdlog::logger::dump_backtrace_(); -} - SPDLOG_INLINE std::shared_ptr spdlog::async_logger::clone(std::string new_name) { auto cloned = std::make_shared(*this); diff --git a/include/spdlog/async_logger.h b/include/spdlog/async_logger.h index 497c9522..0a685186 100644 --- a/include/spdlog/async_logger.h +++ b/include/spdlog/async_logger.h @@ -54,10 +54,8 @@ public: protected: void sink_it_(const details::log_msg &msg) override; void flush_() override; - void dump_backtrace_() override; void backend_sink_it_(const details::log_msg &incoming_log_msg); void backend_flush_(); - void backend_dump_backtrace_(); private: std::weak_ptr thread_pool_; diff --git a/include/spdlog/details/backtracer.h b/include/spdlog/details/backtracer.h new file mode 100644 index 00000000..bdd151ae --- /dev/null +++ b/include/spdlog/details/backtracer.h @@ -0,0 +1,45 @@ +// Copyright(c) 2015-present, Gabi Melman & spdlog contributors. +// Distributed under the MIT License (http://opensource.org/licenses/MIT) + +#pragma once + +#include "spdlog/common.h" +#include "spdlog/details/log_msg_buffer.h" +#include "spdlog/details/circular_q.h" +#include "spdlog/sinks/sink.h" +#include + +// Store log messages in circular buffer. +// Useful for storing debug data in case of error/warning happens. + +namespace spdlog { +namespace details { +class backtracer +{ + std::mutex mutex_; + circular_q messages_; + +public: + explicit backtracer(size_t n_message) + : messages_{n_message} + {} + + void add_msg(const log_msg &msg) + { + std::lock_guard lock{mutex_}; + messages_.push_back(log_msg_buffer{msg}); + } + + // pop all items in the q and apply the give fun on each of them. + void foreach_pop(std::function fun) + { + while (!messages_.empty()) + { + log_msg_buffer popped; + messages_.pop_front(popped); + fun(popped); + } + } +}; +} // namespace details +} // namespace spdlog \ No newline at end of file diff --git a/include/spdlog/details/thread_pool-inl.h b/include/spdlog/details/thread_pool-inl.h index c9b4852c..77d0b1fb 100644 --- a/include/spdlog/details/thread_pool-inl.h +++ b/include/spdlog/details/thread_pool-inl.h @@ -62,11 +62,6 @@ void SPDLOG_INLINE thread_pool::post_flush(async_logger_ptr &&worker_ptr, async_ post_async_msg_(async_msg(std::move(worker_ptr), async_msg_type::flush), overflow_policy); } -void SPDLOG_INLINE thread_pool::post_dump_backtrace(async_logger_ptr &&worker_ptr, async_overflow_policy overflow_policy) -{ - post_async_msg_(async_msg(std::move(worker_ptr), async_msg_type::dump_backtrace), overflow_policy); -} - size_t SPDLOG_INLINE thread_pool::overrun_counter() { return q_.overrun_counter(); @@ -114,18 +109,17 @@ bool SPDLOG_INLINE thread_pool::process_next_msg_() return true; } - case async_msg_type ::dump_backtrace: - { - incoming_async_msg.worker_ptr->backend_dump_backtrace_(); - return true; - } - case async_msg_type::terminate: { return false; } + + default: + { + assert(false && "Unexpected async_msg_type"); } - assert(false && "Unexpected async_msg_type"); + } + return true; } diff --git a/include/spdlog/details/thread_pool.h b/include/spdlog/details/thread_pool.h index 577e1243..81bd12de 100644 --- a/include/spdlog/details/thread_pool.h +++ b/include/spdlog/details/thread_pool.h @@ -24,8 +24,7 @@ enum class async_msg_type { log, flush, - terminate, - dump_backtrace + terminate }; #include "spdlog/details/log_msg_buffer.h" @@ -97,7 +96,6 @@ public: void post_log(async_logger_ptr &&worker_ptr, const details::log_msg &msg, async_overflow_policy overflow_policy); void post_flush(async_logger_ptr &&worker_ptr, async_overflow_policy overflow_policy); - void post_dump_backtrace(async_logger_ptr &&worker_ptr, async_overflow_policy overflow_policy); size_t overrun_counter(); private: diff --git a/include/spdlog/logger-inl.h b/include/spdlog/logger-inl.h index ba0e54ce..a482d17e 100644 --- a/include/spdlog/logger-inl.h +++ b/include/spdlog/logger-inl.h @@ -8,7 +8,7 @@ #endif #include "spdlog/sinks/sink.h" -#include "spdlog/sinks/backtrace_sink.h" +#include "spdlog/details/backtracer.h" #include "spdlog/details/pattern_formatter.h" #include @@ -22,7 +22,7 @@ SPDLOG_INLINE logger::logger(const logger &other) , level_(other.level_.load(std::memory_order_relaxed)) , flush_level_(other.flush_level_.load(std::memory_order_relaxed)) , custom_err_handler_(other.custom_err_handler_) - , backtrace_sink_(other.backtrace_sink_) + , tracer_(other.tracer_) {} SPDLOG_INLINE logger::logger(logger &&other) SPDLOG_NOEXCEPT : name_(std::move(other.name_)), @@ -30,7 +30,7 @@ SPDLOG_INLINE logger::logger(logger &&other) SPDLOG_NOEXCEPT : name_(std::move(o level_(other.level_.load(std::memory_order_relaxed)), flush_level_(other.flush_level_.load(std::memory_order_relaxed)), custom_err_handler_(std::move(other.custom_err_handler_)), - backtrace_sink_(std::move(other.backtrace_sink_)) + tracer_(std::move(other.tracer_)) {} @@ -56,7 +56,7 @@ SPDLOG_INLINE void logger::swap(spdlog::logger &other) SPDLOG_NOEXCEPT other.flush_level_.store(tmp); custom_err_handler_.swap(other.custom_err_handler_); - backtrace_sink_.swap(other.backtrace_sink_); + tracer_.swap(other.tracer_); } SPDLOG_INLINE void swap(logger &a, logger &b) @@ -66,6 +66,11 @@ SPDLOG_INLINE void swap(logger &a, logger &b) SPDLOG_INLINE void logger::log(source_loc loc, level::level_enum lvl, string_view_t msg) { + if (tracer_) + { + save_backtrace_(details::log_msg(loc, string_view_t(name_), lvl, msg)); + } + if (!should_log(lvl)) { return; @@ -87,16 +92,7 @@ SPDLOG_INLINE bool logger::should_log(level::level_enum msg_level) const SPDLOG_INLINE void logger::set_level(level::level_enum log_level) { - if (backtrace_sink_) - { - auto tracer = static_cast(backtrace_sink_.get()); - tracer->set_filter_level(log_level); - level_.store(level::trace); - } - else - { - level_.store(log_level); - } + level_.store(log_level); } SPDLOG_INLINE level::level_enum logger::level() const @@ -136,24 +132,13 @@ SPDLOG_INLINE void logger::set_pattern(std::string pattern, pattern_time_type ti // create new backtrace sink and move to it all our child sinks SPDLOG_INLINE void logger::enable_backtrace(size_t n_messages) { - if (!backtrace_sink_) - { - backtrace_sink_ = std::make_shared(std::move(sinks_), level(), n_messages); - sinks().push_back(backtrace_sink_); - level_.store(level::trace); // pass all messages to the backtrace sink. - } + tracer_ = std::make_shared(n_messages); } // restore orig sinks and level and delete the backtrace sink SPDLOG_INLINE void logger::disable_backtrace() { - if (backtrace_sink_) - { - auto tracer = static_cast(backtrace_sink_.get()); - sinks_ = std::move(tracer->sinks()); - level_.store(tracer->get_filter_level()); - backtrace_sink_.reset(); - } + tracer_.reset(); } SPDLOG_INLINE void logger::dump_backtrace() @@ -235,16 +220,19 @@ SPDLOG_INLINE void logger::flush_() } } +SPDLOG_INLINE void logger::save_backtrace_(const details::log_msg &msg) +{ + tracer_->add_msg(msg); +} + SPDLOG_INLINE void logger::dump_backtrace_() { - if (backtrace_sink_) + using details::log_msg; + if (tracer_) { - auto tracer = static_cast(backtrace_sink_.get()); - SPDLOG_TRY - { - tracer->dump_backtrace(name()); - } - SPDLOG_LOGGER_CATCH() + sink_it_(log_msg{name(), level::info, "****************** Backtrace Start ******************"}); + tracer_->foreach_pop([this](const details::log_msg &msg) { this->sink_it_(msg); }); + sink_it_(log_msg{name(), level::info, "****************** Backtrace End ********************"}); } } diff --git a/include/spdlog/logger.h b/include/spdlog/logger.h index 3fea1965..4c686ba8 100644 --- a/include/spdlog/logger.h +++ b/include/spdlog/logger.h @@ -38,6 +38,11 @@ #endif namespace spdlog { + +namespace details { +class backtracer; +} + class logger { public: @@ -81,6 +86,10 @@ public: fmt::format_to(buf, fmt, args...); details::log_msg log_msg(loc, name_, lvl, string_view_t(buf.data(), buf.size())); sink_it_(log_msg); + if (tracer_) + { + save_backtrace_(log_msg); + } } SPDLOG_LOGGER_CATCH() } @@ -149,6 +158,10 @@ public: template::value, T>::type * = nullptr> void log(source_loc loc, level::level_enum lvl, const T &msg) { + if (tracer_) + { + save_backtrace_(details::log_msg(loc, name_, lvl, msg)); + } if (!should_log(lvl)) { return; @@ -164,6 +177,13 @@ public: T>::type * = nullptr> void log(source_loc loc, level::level_enum lvl, const T &msg) { + if (tracer_) + { + fmt::memory_buffer buf; + fmt::format_to(buf, "{}", msg); + save_backtrace_(details::log_msg(loc, name_, lvl, string_view_t(buf.data(), buf.size()))); + } + if (!should_log(lvl)) { return; @@ -323,7 +343,9 @@ public: void set_pattern(std::string pattern, pattern_time_type time_type = pattern_time_type::local); - void enable_backtrace(size_t n_messages = 16); + // backtrace support. + // efficiently store all debug/trace messages in a circular buffer until needed for debugging. + void enable_backtrace(size_t n_messages); void disable_backtrace(); void dump_backtrace(); @@ -349,12 +371,13 @@ protected: spdlog::level_t level_{level::info}; spdlog::level_t flush_level_{level::off}; err_handler custom_err_handler_{nullptr}; - sink_ptr backtrace_sink_; - // bool backtrace_enabled_{false}; + std::shared_ptr tracer_; virtual void sink_it_(const details::log_msg &msg); virtual void flush_(); - virtual void dump_backtrace_(); + + void save_backtrace_(const details::log_msg &msg); + void dump_backtrace_(); bool should_flush_(const details::log_msg &msg); // handle errors during logging. diff --git a/include/spdlog/sinks/backtrace_sink.h b/include/spdlog/sinks/backtrace_sink.h deleted file mode 100644 index fe265ac5..00000000 --- a/include/spdlog/sinks/backtrace_sink.h +++ /dev/null @@ -1,89 +0,0 @@ -// Copyright(c) 2015-present, Gabi Melman & spdlog contributors. -// Distributed under the MIT License (http://opensource.org/licenses/MIT) - -#pragma once - -#include "dist_sink.h" -#include "spdlog/common.h" -#include "spdlog/details/log_msg_buffer.h" -#include "spdlog/details/circular_q.h" - -#include -#include -#include - -// Store log messages in circular buffer. -// If it encounters a message with high enough level, it will send all previous message to it child sinks. -// Useful for storing debug data in case of error/warning happens. - -namespace spdlog { -namespace sinks { -template -class backtrace_sink : public dist_sink -{ -public: - backtrace_sink(std::vector> &&child_sinks, spdlog::level::level_enum filter_level, size_t n_messages) - : filter_level_{filter_level} - , traceback_msgs_{n_messages} - { - dist_sink::set_sinks(std::move(child_sinks)); - } - - void set_filter_level(spdlog::level::level_enum filter_level) - { - std::lock_guard lock(base_sink::mutex_); - filter_level_ = filter_level; - } - - spdlog::level::level_enum get_filter_level() - { - std::lock_guard lock(base_sink::mutex_); - return filter_level_; - } - - void dump_backtrace(string_view_t logger_name) - { - std::lock_guard lock(base_sink::mutex_); - dump_backtrace_(logger_name); - } - -protected: - spdlog::level::level_enum filter_level_; - details::circular_q traceback_msgs_; - - // save the messages in a circular queue - void sink_it_(const details::log_msg &msg) override - { - traceback_msgs_.push_back(details::log_msg_buffer(msg)); - - if (msg.level >= filter_level_) - { - dist_sink::sink_it_(msg); - } - } - - void dump_backtrace_(string_view_t logger_name) - { - if (traceback_msgs_.empty()) - { - return; - } - dist_sink::sink_it_( - details::log_msg{logger_name, level::info, "********************* Backtrace Start *********************"}); - - do - { - details::log_msg_buffer popped; - traceback_msgs_.pop_front(popped); - dist_sink::sink_it_(popped); - } while (!traceback_msgs_.empty()); - - dist_sink::sink_it_( - details::log_msg{logger_name, level::info, "********************* Backtrace End ***********************"}); - } -}; - -using backtrace_sink_mt = backtrace_sink; - -} // namespace sinks -} // namespace spdlog