diff --git a/include/wsrep/client_context.hpp b/include/wsrep/client_context.hpp index 8bcac59..fb7dc64 100644 --- a/include/wsrep/client_context.hpp +++ b/include/wsrep/client_context.hpp @@ -392,7 +392,7 @@ namespace wsrep friend class client_toi_mode; friend class transaction_context; - + void debug_log_state(const char*) const; /*! * Set client state. */ diff --git a/src/client_context.cpp b/src/client_context.cpp index 558c20c..c3e9fe4 100644 --- a/src/client_context.cpp +++ b/src/client_context.cpp @@ -4,6 +4,7 @@ #include "wsrep/client_context.hpp" #include "wsrep/compiler.hpp" +#include "wsrep/logger.hpp" #include #include @@ -29,6 +30,7 @@ void wsrep::client_context::override_error(enum wsrep::client_error error) int wsrep::client_context::before_command() { wsrep::unique_lock lock(mutex_); + debug_log_state("before_command: enter"); assert(state_ == s_idle); if (server_context_.rollback_mode() == wsrep::server_context::rm_sync) { @@ -63,6 +65,8 @@ int wsrep::client_context::before_command() wsrep::transaction_context::s_aborted); assert(transaction_.active() == false); assert(current_error() != wsrep::e_success); + debug_log_state("before_command: error"); + return 1; } else if (transaction_.state() == wsrep::transaction_context::s_aborted) { @@ -74,15 +78,18 @@ int wsrep::client_context::before_command() (void)transaction_.after_statement(); lock.lock(); assert(transaction_.active() == false); + debug_log_state("before_command: error"); + return 1; } - return 1; } + debug_log_state("before_command: success"); return 0; } void wsrep::client_context::after_command_before_result() { wsrep::unique_lock lock(mutex_); + debug_log_state("after_command_before_result: enter"); assert(state() == s_exec); if (transaction_.active() && transaction_.state() == wsrep::transaction_context::s_must_abort) @@ -96,11 +103,13 @@ void wsrep::client_context::after_command_before_result() assert(current_error() != wsrep::e_success); } state(lock, s_result); + debug_log_state("after_command_before_result: leave"); } void wsrep::client_context::after_command_after_result() { wsrep::unique_lock lock(mutex_); + debug_log_state("after_command_after_result_enter"); assert(state() == s_result); assert(transaction_.state() != wsrep::transaction_context::s_aborting); if (transaction_.active() && @@ -117,11 +126,13 @@ void wsrep::client_context::after_command_after_result() current_error_ = wsrep::e_success; } state(lock, s_idle); + debug_log_state("after_command_after_result: leave"); } int wsrep::client_context::before_statement() { wsrep::unique_lock lock(mutex_); + debug_log_state("before_statement: enter"); #if 0 /*! * \todo It might be beneficial to implement timed wait for @@ -138,8 +149,10 @@ int wsrep::client_context::before_statement() transaction_.state() == wsrep::transaction_context::s_must_abort) { // Rollback and cleanup will happen in after_command_before_result() + debug_log_state("before_statement_error"); return 1; } + debug_log_state("before_statement: success"); return 0; } @@ -147,6 +160,7 @@ enum wsrep::client_context::after_statement_result wsrep::client_context::after_statement() { // wsrep::unique_lock lock(mutex_); + debug_log_state("after_statement: enter"); assert(state() == s_exec); #if 0 /*! @@ -158,18 +172,32 @@ wsrep::client_context::after_statement() { if (is_autocommit()) { + debug_log_state("after_statement: may_retry"); return asr_may_retry; } else { + debug_log_state("after_statement: error"); return asr_error; } } + debug_log_state("after_statement: success"); return asr_success; } // Private +void wsrep::client_context::debug_log_state(const char* context) const +{ + if (debug_log_level() >= 1) + { + wsrep::log_debug() << "client_context: " << context + << ": server: " << server_context_.name() + << " client: " << id_.get() + << " current_error: " << current_error_; + } +} + void wsrep::client_context::state( wsrep::unique_lock& lock WSREP_UNUSED, enum wsrep::client_context::state state) diff --git a/src/dbms_simulator.cpp b/src/dbms_simulator.cpp index 592b365..dd6d814 100644 --- a/src/dbms_simulator.cpp +++ b/src/dbms_simulator.cpp @@ -78,6 +78,7 @@ public: void start(wsrep::client_context* cc) { + // wsrep::log_debug() << "Start: " << cc; wsrep::unique_lock lock(se_.mutex_); if (se_.transactions_.insert(cc).second == false) { @@ -88,6 +89,7 @@ public: void commit() { + // wsrep::log_debug() << "Commit: " << cc_; if (cc_) { wsrep::unique_lock lock(se_.mutex_); @@ -99,6 +101,7 @@ public: void abort() { + // wsrep::log_debug() << "Abort: " << cc_; if (cc_) { wsrep::unique_lock lock(se_.mutex_); @@ -133,7 +136,7 @@ public: lock.unlock(); if (victim_txc->bf_abort(victim_txc_lock, txc.seqno())) { - wsrep::log() << "BF aborted " << victim_txc->id().get(); + // wsrep::log() << "BF aborted " << victim_txc->id().get(); ++bf_aborts_; } } @@ -359,9 +362,9 @@ private: } int rollback() override { - wsrep::log() << "rollback: " << transaction().id().get() - << "state: " - << wsrep::to_string(transaction().state()); + // wsrep::log() << "rollback: " << transaction().id().get() + // << "state: " + // << wsrep::to_string(transaction().state()); before_rollback(); se_trx_.abort(); after_rollback(); @@ -371,7 +374,7 @@ private: void will_replay(wsrep::transaction_context&) override { } int replay(wsrep::transaction_context& txc) override { - wsrep::log() << "replay: " << txc.id().get(); + // wsrep::log() << "replay: " << txc.id().get(); wsrep::client_applier_mode applier_mode(*this); ++stats_.replays; return provider().replay(txc.ws_handle(), this); @@ -400,6 +403,7 @@ private: int client_command(Func f) { int err(before_command()); + // wsrep::log_debug() << "before_command: " << err; // If err != 0, transaction was BF aborted while client idle if (err == 0) { @@ -413,11 +417,13 @@ private: after_command_before_result(); if (current_error()) { + // wsrep::log_info() << "Current error"; assert(transaction_.state() == wsrep::transaction_context::s_aborted); err = 1; } after_command_after_result(); + // wsrep::log_info() << "client_command(): " << err; return err; } @@ -427,6 +433,7 @@ private: int err = client_command( [&]() { + // wsrep::log_debug() << "Start transaction"; err = start_transaction(server_.next_transaction_id()); assert(err == 0); se_trx_.start(this); @@ -435,6 +442,7 @@ private: err = err || client_command( [&]() { + // wsrep::log_debug() << "Generate write set"; assert(transaction().active()); assert(err == 0); int data(std::rand() % 10000000); @@ -453,6 +461,7 @@ private: err = err || client_command( [&]() { + // wsrep::log_debug() << "Commit"; assert(err == 0); if (do_2pc()) { @@ -467,8 +476,8 @@ private: }); assert(err || - transaction().state() == wsrep::transaction_context::s_aborted || - transaction().state() == wsrep::transaction_context::s_committed); + transaction().state() == wsrep::transaction_context::s_aborted || + transaction().state() == wsrep::transaction_context::s_committed); assert(se_trx_.active() == false); assert(transaction().active() == false); switch (transaction().state()) diff --git a/src/transaction_context.cpp b/src/transaction_context.cpp index 6f329fe..fde4a80 100644 --- a/src/transaction_context.cpp +++ b/src/transaction_context.cpp @@ -13,6 +13,13 @@ #include #include +#define WSREP_TC_LOG_DEBUG(level, msg) \ + do { \ + if (client_context_.debug_log_level() < level) \ + { } \ + else wsrep::log_debug() << msg; \ + } while (0) + // Public wsrep::transaction_context::transaction_context( @@ -489,12 +496,13 @@ bool wsrep::transaction_context::bf_abort( if (active() == false) { - wsrep::log() << "Transaction not active, skipping bf abort"; + WSREP_TC_LOG_DEBUG(1, "Transaction not active, skipping bf abort"); } else if (ordered() && seqno() < bf_seqno) { - wsrep::log() << "Not allowed to BF abort transaction ordered before " - << "aborter: " << seqno() << " < " << bf_seqno; + WSREP_TC_LOG_DEBUG(1, + "Not allowed to BF abort transaction ordered before " + << "aborter: " << seqno() << " < " << bf_seqno); } else { @@ -512,31 +520,26 @@ bool wsrep::transaction_context::bf_abort( switch (status) { case wsrep::provider::success: - if (client_context_.debug_log_level() >= 1) - { - wsrep::log_debug() << "Seqno " << bf_seqno - << " succesfully BF aborted " << id_.get() - << " victim_seqno " << victim_seqno; - } + WSREP_TC_LOG_DEBUG(1, "Seqno " << bf_seqno + << " succesfully BF aborted " << id_.get() + << " victim_seqno " << victim_seqno); bf_abort_state_ = state(); state(lock, s_must_abort); ret = true; break; default: - if (client_context_.debug_log_level() >= 1) - { - wsrep::log_debug() << "Seqno " << bf_seqno - << " failed to BF abort " << id_.get() - << " with status " << status - << " victim_seqno " << victim_seqno; - } + WSREP_TC_LOG_DEBUG(1, + "Seqno " << bf_seqno + << " failed to BF abort " << id_.get() + << " with status " << status + << " victim_seqno " << victim_seqno); break; } break; } default: - wsrep::log() << "BF abort not allowed in state " - << wsrep::to_string(state()); + WSREP_TC_LOG_DEBUG(1, "BF abort not allowed in state " + << wsrep::to_string(state())); break; } } @@ -604,7 +607,7 @@ void wsrep::transaction_context::state( os << "unallowed state transition for transaction " << id_.get() << ": " << wsrep::to_string(state_) << " -> " << wsrep::to_string(next_state); - wsrep::log() << os.str(); + wsrep::log_error() << os.str(); throw wsrep::runtime_error(os.str()); } } @@ -854,14 +857,12 @@ void wsrep::transaction_context::cleanup() void wsrep::transaction_context::debug_log_state( const char* context) const { - if (client_context_.debug_log_level() >= 1) - { - wsrep::log_debug() << context - << ": server: " << client_context_.server_context().name() - << ": client: " << client_context_.id().get() - << " trx: " << int64_t(id_.get()) - << " state: " << wsrep::to_string(state_) - << " error: " - << wsrep::to_string(client_context_.current_error()); - } + WSREP_TC_LOG_DEBUG( + 1, context + << ": server: " << client_context_.server_context().name() + << " client: " << client_context_.id().get() + << " trx: " << int64_t(id_.get()) + << " state: " << wsrep::to_string(state_) + << " error: " + << wsrep::to_string(client_context_.current_error())); } diff --git a/src/transaction_context_test.cpp b/src/transaction_context_test.cpp index f6083e2..de8abfc 100644 --- a/src/transaction_context_test.cpp +++ b/src/transaction_context_test.cpp @@ -141,6 +141,13 @@ BOOST_FIXTURE_TEST_CASE_TEMPLATE(transaction_context_1pc, T, BOOST_REQUIRE(tc.id() == wsrep::transaction_id(1)); BOOST_REQUIRE(tc.state() == wsrep::transaction_context::s_executing); + // Verify that the commit can be succesfully executed in separate command + BOOST_REQUIRE(cc.after_statement() == wsrep::client_context::asr_success); + cc.after_command_before_result(); + cc.after_command_after_result(); + BOOST_REQUIRE(cc.current_error() == wsrep::e_success); + BOOST_REQUIRE(cc.before_command() == 0); + BOOST_REQUIRE(cc.before_statement() == 0); // Run before commit BOOST_REQUIRE(cc.before_commit() == 0); BOOST_REQUIRE(tc.state() == wsrep::transaction_context::s_committing); @@ -940,7 +947,7 @@ BOOST_FIXTURE_TEST_CASE_TEMPLATE( cc.after_statement(); cc.after_command_before_result(); cc.after_command_after_result(); - cc.before_command(); + BOOST_REQUIRE(cc.before_command() == 0); BOOST_REQUIRE(tc.active()); BOOST_REQUIRE(tc.state() == wsrep::transaction_context::s_executing); wsrep_test::bf_abort_unordered(cc); diff --git a/src/wsrep_provider_v26.cpp b/src/wsrep_provider_v26.cpp index 6b5b834..52b2dc7 100644 --- a/src/wsrep_provider_v26.cpp +++ b/src/wsrep_provider_v26.cpp @@ -323,7 +323,7 @@ namespace wsrep::stid(wsrep::id(meta->stid.node.data, sizeof(meta->stid.node.data)), meta->stid.trx, - meta->stid.conn), wsrep::seqno(meta->depends_on), + meta->stid.conn), wsrep::seqno(seqno_from_native(meta->depends_on)), map_flags_from_native(flags)); if (ret == WSREP_CB_SUCCESS && client_context->server_context().on_apply(