From be98517cb3886fbd5d23b2db30d4fc24dee2d463 Mon Sep 17 00:00:00 2001 From: mkaruza Date: Tue, 12 Feb 2019 10:44:26 +0100 Subject: [PATCH] Debug log level implementation Debug log will now filter output based on debug level that is enabled. --- CMakeLists.txt | 3 ++ include/wsrep/client_state.hpp | 2 +- include/wsrep/logger.hpp | 26 ++++++++++++ include/wsrep/server_state.hpp | 18 +++------ include/wsrep/streaming_context.hpp | 20 ++++++--- src/client_state.cpp | 18 ++++----- src/logger.cpp | 11 +++++ src/server_state.cpp | 44 +++++++++++++------- src/transaction.cpp | 63 +++++++++++++++-------------- 9 files changed, 131 insertions(+), 74 deletions(-) diff --git a/CMakeLists.txt b/CMakeLists.txt index eb6904e..1b4488e 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -27,6 +27,9 @@ option(WSREP_LIB_WITH_COVERAGE "Compile with coverage instrumentation" OFF) option(WSREP_LIB_STRICT_BUILD_FLAGS "Compile with strict build flags" OFF) option(WSREP_LIB_MAINTAINER_MODE "Fail compilation on any warnings" OFF) +# Compiler options +set(CMAKE_CXX_STANDARD 11) + # CXX flags set(CMAKE_CXX_FLAGS "${CMAKE_CXX_FLAGS} -Wall -Wextra -Woverloaded-virtual -g") diff --git a/include/wsrep/client_state.hpp b/include/wsrep/client_state.hpp index 6d997fb..9f87176 100644 --- a/include/wsrep/client_state.hpp +++ b/include/wsrep/client_state.hpp @@ -674,7 +674,7 @@ namespace wsrep int debug_log_level() const { return std::max(debug_log_level_, - server_state_.debug_log_level()); + wsrep::log::debug_log_level()); } // diff --git a/include/wsrep/logger.hpp b/include/wsrep/logger.hpp index d1b6ad8..7b82ccb 100644 --- a/include/wsrep/logger.hpp +++ b/include/wsrep/logger.hpp @@ -25,6 +25,12 @@ #include #include +#include + +#define WSREP_LOG_DEBUG(debug_level_fn, debug_level, msg) \ + do { \ + if (debug_level_fn >= debug_level) wsrep::log_debug() << msg; \ + } while (0) namespace wsrep { @@ -39,6 +45,14 @@ namespace wsrep error }; + enum debug_level + { + debug_level_server_state = 1, + debug_level_transaction, + debug_level_streaming, + debug_level_client_state + }; + /** * Signature for user defined logger callback function. */ @@ -85,6 +99,17 @@ namespace wsrep * Set user defined logger callback function. */ static void logger_fn(logger_fn_type); + + /** + * Set debug log level from client + */ + static void debug_log_level(int debug_level); + + /** + * Get current debug log level + */ + static int debug_log_level(); + private: log(const log&); log& operator=(const log&); @@ -94,6 +119,7 @@ namespace wsrep static wsrep::mutex& mutex_; static std::ostream& os_; static logger_fn_type logger_fn_; + static std::atomic_int debug_log_level_; }; class log_error : public log diff --git a/include/wsrep/server_state.hpp b/include/wsrep/server_state.hpp index e93610f..71cf9ad 100644 --- a/include/wsrep/server_state.hpp +++ b/include/wsrep/server_state.hpp @@ -87,6 +87,7 @@ #include "id.hpp" #include "view.hpp" #include "transaction_id.hpp" +#include "logger.hpp" #include "provider.hpp" #include "compiler.hpp" @@ -542,17 +543,10 @@ namespace wsrep * - 0 - No debug logging. * - 1..n - Debug logging with increasing verbosity. */ - void debug_log_level(int level) { debug_log_level_ = level; } - - /** - * - */ - int debug_log_level() const { return debug_log_level_; } - - /** - * @todo Set filter for debug logging. - */ - void debug_log_filter(const std::string&); + void debug_log_level(int level) + { + wsrep::log::debug_log_level(level); + } wsrep::mutex& mutex() { return mutex_; } @@ -611,7 +605,6 @@ namespace wsrep , connected_gtid_() , current_view_() , last_committed_gtid_() - , debug_log_level_(0) { } private: @@ -701,7 +694,6 @@ namespace wsrep wsrep::gtid connected_gtid_; wsrep::view current_view_; wsrep::gtid last_committed_gtid_; - int debug_log_level_; }; diff --git a/include/wsrep/streaming_context.hpp b/include/wsrep/streaming_context.hpp index f1118aa..bccad9d 100644 --- a/include/wsrep/streaming_context.hpp +++ b/include/wsrep/streaming_context.hpp @@ -62,12 +62,16 @@ namespace wsrep { if (fragment_size) { - wsrep::log_debug() << "Enabling streaming: " - << fragment_unit << " " << fragment_size; + WSREP_LOG_DEBUG(wsrep::log::debug_log_level(), + wsrep::log::debug_level_streaming, + "Enabling streaming: " + << fragment_unit << " " << fragment_size); } else { - wsrep::log_debug() << "Disabling streaming"; + WSREP_LOG_DEBUG(wsrep::log::debug_log_level(), + wsrep::log::debug_level_streaming, + "Disabling streaming"); } fragment_unit_ = fragment_unit; fragment_size_ = fragment_size; @@ -76,8 +80,10 @@ namespace wsrep void enable(enum fragment_unit fragment_unit, size_t fragment_size) { - wsrep::log_debug() << "Enabling streaming: " - << fragment_unit << " " << fragment_size; + WSREP_LOG_DEBUG(wsrep::log::debug_log_level(), + wsrep::log::debug_level_streaming, + "Enabling streaming: " + << fragment_unit << " " << fragment_size); assert(fragment_size > 0); fragment_unit_ = fragment_unit; fragment_size_ = fragment_size; @@ -89,7 +95,9 @@ namespace wsrep void disable() { - wsrep::log_debug() << "Disabling streaming"; + WSREP_LOG_DEBUG(wsrep::log::debug_log_level(), + wsrep::log::debug_level_streaming, + "Disabling streaming"); fragment_size_ = 0; } diff --git a/src/client_state.cpp b/src/client_state.cpp index 95e8a76..e5998f1 100644 --- a/src/client_state.cpp +++ b/src/client_state.cpp @@ -454,15 +454,15 @@ void wsrep::client_state::update_last_written_gtid(const wsrep::gtid& gtid) void wsrep::client_state::debug_log_state(const char* context) const { - if (debug_log_level() >= 1) - { - wsrep::log_debug() << context - << "(" << id_.get() - << "," << to_c_string(state_) - << "," << to_c_string(mode_) - << "," << wsrep::to_string(current_error_) - << ")"; - } + WSREP_LOG_DEBUG(debug_log_level(), + wsrep::log::debug_level_client_state, + context + << "(" << id_.get() + << "," << to_c_string(state_) + << "," << to_c_string(mode_) + << "," << wsrep::to_string(current_error_) + << ")"); + } void wsrep::client_state::state( diff --git a/src/logger.cpp b/src/logger.cpp index 65ad9ab..058a42a 100644 --- a/src/logger.cpp +++ b/src/logger.cpp @@ -25,8 +25,19 @@ std::ostream& wsrep::log::os_ = std::cout; static wsrep::default_mutex log_mutex_; wsrep::mutex& wsrep::log::mutex_ = log_mutex_; wsrep::log::logger_fn_type wsrep::log::logger_fn_ = 0; +std::atomic_int wsrep::log::debug_log_level_(0); void wsrep::log::logger_fn(wsrep::log::logger_fn_type logger_fn) { logger_fn_ = logger_fn; } + +void wsrep::log::debug_log_level(int debug_log_level) +{ + debug_log_level_.store(debug_log_level, std::memory_order_relaxed); +} + +int wsrep::log::debug_log_level() +{ + return debug_log_level_.load(std::memory_order_relaxed); +} diff --git a/src/server_state.cpp b/src/server_state.cpp index af0b313..4d92ccf 100644 --- a/src/server_state.cpp +++ b/src/server_state.cpp @@ -31,6 +31,7 @@ #include #include + ////////////////////////////////////////////////////////////////////////////// // Helpers // ////////////////////////////////////////////////////////////////////////////// @@ -168,10 +169,11 @@ static int apply_write_set(wsrep::server_state& server_state, // may be delivered here. The message below has // been intentionally turned into a debug message, // rather than warning. - wsrep::log_debug() - << "Could not find applier context for " - << ws_meta.server_id() - << ": " << ws_meta.transaction_id(); + WSREP_LOG_DEBUG(wsrep::log::debug_log_level(), + wsrep::log::debug_level_server_state, + "Could not find applier context for " + << ws_meta.server_id() + << ": " << ws_meta.transaction_id()); ret = high_priority_service.log_dummy_write_set( ws_handle, ws_meta); } @@ -435,7 +437,9 @@ wsrep::seqno wsrep::server_state::desync_and_pause() // communicate with the rest of the cluster. However, this // error can be tolerated because if the provider can be // paused succesfully below. - wsrep::log_debug() << "Failed to desync server before pause"; + WSREP_LOG_DEBUG(wsrep::log::debug_log_level(), + wsrep::log::debug_level_server_state, + "Failed to desync server before pause"); desync_successful = false; } else @@ -967,7 +971,9 @@ void wsrep::server_state::start_streaming_client( wsrep::client_state* client_state) { wsrep::unique_lock lock(mutex_); - wsrep::log_debug() << "Start streaming client: " << client_state->id(); + WSREP_LOG_DEBUG(wsrep::log::debug_log_level(), + wsrep::log::debug_level_server_state, + "Start streaming client: " << client_state->id()); if (streaming_clients_.insert( std::make_pair(client_state->id(), client_state)).second == false) { @@ -981,8 +987,10 @@ void wsrep::server_state::convert_streaming_client_to_applier( wsrep::client_state* client_state) { wsrep::unique_lock lock(mutex_); - wsrep::log_debug() << "Convert streaming client to applier " - << client_state->id(); + WSREP_LOG_DEBUG(wsrep::log::debug_log_level(), + wsrep::log::debug_level_server_state, + "Convert streaming client to applier " + << client_state->id()); streaming_clients_map::iterator i( streaming_clients_.find(client_state->id())); assert(i != streaming_clients_.end()); @@ -1027,7 +1035,9 @@ void wsrep::server_state::stop_streaming_client( wsrep::client_state* client_state) { wsrep::unique_lock lock(mutex_); - wsrep::log_debug() << "Stop streaming client: " << client_state->id(); + WSREP_LOG_DEBUG(wsrep::log::debug_log_level(), + wsrep::log::debug_level_server_state, + "Stop streaming client: " << client_state->id()); streaming_clients_map::iterator i( streaming_clients_.find(client_state->id())); assert(i != streaming_clients_.end()); @@ -1157,9 +1167,11 @@ void wsrep::server_state::state( assert(0); } - wsrep::log_debug() << "server " << name_ << " state change: " - << to_c_string(state_) << " -> " - << to_c_string(state); + WSREP_LOG_DEBUG(wsrep::log::debug_log_level(), + wsrep::log::debug_level_server_state, + "server " << name_ << " state change: " + << to_c_string(state_) << " -> " + << to_c_string(state)); state_hist_.push_back(state_); server_service_.log_state_change(state_, state); state_ = state; @@ -1255,9 +1267,11 @@ void wsrep::server_state::close_orphaned_sr_transactions( server_id_cmp(i->first.first)) == current_view_.members().end()) { - wsrep::log_debug() << "Removing SR fragments for " - << i->first.first - << ", " << i->first.second; + WSREP_LOG_DEBUG(wsrep::log::debug_log_level(), + wsrep::log::debug_level_server_state, + "Removing SR fragments for " + << i->first.first + << ", " << i->first.second); wsrep::id server_id(i->first.first); wsrep::transaction_id transaction_id(i->first.second); wsrep::high_priority_service* streaming_applier(i->second); diff --git a/src/transaction.cpp b/src/transaction.cpp index 46e38a8..003fd84 100644 --- a/src/transaction.cpp +++ b/src/transaction.cpp @@ -29,14 +29,6 @@ #include #include -#define WSREP_TC_LOG_DEBUG(level, msg) \ - do { \ - if (client_state_.debug_log_level() < level) \ - { } \ - else wsrep::log_debug() << msg; \ - } while (0) - - namespace { class storage_service_deleter @@ -824,7 +816,9 @@ bool wsrep::transaction::bf_abort( if (active() == false) { - WSREP_TC_LOG_DEBUG(1, "Transaction not active, skipping bf abort"); + WSREP_LOG_DEBUG(client_state_.debug_log_level(), + wsrep::log::debug_level_transaction, + "Transaction not active, skipping bf abort"); } else { @@ -842,26 +836,31 @@ bool wsrep::transaction::bf_abort( switch (status) { case wsrep::provider::success: - WSREP_TC_LOG_DEBUG(1, "Seqno " << bf_seqno - << " succesfully BF aborted " << id_ - << " victim_seqno " << victim_seqno); + WSREP_LOG_DEBUG(client_state_.debug_log_level(), + wsrep::log::debug_level_transaction, + "Seqno " << bf_seqno + << " succesfully BF aborted " << id_ + << " victim_seqno " << victim_seqno); bf_abort_state_ = state(); state(lock, s_must_abort); ret = true; break; default: - WSREP_TC_LOG_DEBUG(1, - "Seqno " << bf_seqno - << " failed to BF abort " << id_ - << " with status " << status - << " victim_seqno " << victim_seqno); + WSREP_LOG_DEBUG(client_state_.debug_log_level(), + wsrep::log::debug_level_transaction, + "Seqno " << bf_seqno + << " failed to BF abort " << id_ + << " with status " << status + << " victim_seqno " << victim_seqno); break; } break; } default: - WSREP_TC_LOG_DEBUG(1, "BF abort not allowed in state " - << wsrep::to_string(state())); + WSREP_LOG_DEBUG(client_state_.debug_log_level(), + wsrep::log::debug_level_transaction, + "BF abort not allowed in state " + << wsrep::to_string(state())); break; } } @@ -937,13 +936,13 @@ void wsrep::transaction::state( wsrep::unique_lock& lock __attribute__((unused)), enum wsrep::transaction::state next_state) { - if (client_state_.debug_log_level() >= 1) - { - log_debug() << "client: " << client_state_.id().get() + WSREP_LOG_DEBUG(client_state_.debug_log_level(), + wsrep::log::debug_level_transaction, + "client: " << client_state_.id().get() << " txc: " << id().get() << " state: " << to_string(state_) - << " -> " << to_string(next_state); - } + << " -> " << to_string(next_state)); + assert(lock.owns_lock()); // BF aborter is allowed to change the state to must abort and // further to aborting and aborted if the background rollbacker @@ -1524,8 +1523,10 @@ void wsrep::transaction::cleanup() void wsrep::transaction::debug_log_state( const char* context) const { - WSREP_TC_LOG_DEBUG( - 1, context + WSREP_LOG_DEBUG( + client_state_.debug_log_level(), + wsrep::log::debug_level_transaction, + context << "\n server: " << server_id_ << ", client: " << int64_t(client_state_.id().get()) << ", state: " << wsrep::to_c_string(client_state_.state()) @@ -1554,8 +1555,10 @@ void wsrep::transaction::debug_log_state( void wsrep::transaction::debug_log_key_append(const wsrep::key& key) { - WSREP_TC_LOG_DEBUG(2, "key_append" - << "trx_id: " - << int64_t(id().get()) - << " append key: " << key); + WSREP_LOG_DEBUG(client_state_.debug_log_level(), + wsrep::log::debug_level_transaction, + "key_append: " + << "trx_id: " + << int64_t(id().get()) + << " append key: " << key); }