From 05e71652ba4c2a55560e454e9db93993f00a741d Mon Sep 17 00:00:00 2001 From: Xiaoxi Chen Date: Tue, 20 Aug 2024 00:56:03 +0800 Subject: [PATCH] Track timestamp of each state in repl_dev_ctx. With this we can easily get time diff of each given state, avoid doing the calculation/analysis from grep of logs. Signed-off-by: Xiaoxi Chen --- conanfile.py | 2 +- src/include/homestore/replication/repl_dev.h | 15 +++++++++++---- src/lib/replication/repl_dev/common.cpp | 17 +++++++++++++++-- .../replication/repl_dev/raft_state_machine.cpp | 2 -- 4 files changed, 27 insertions(+), 9 deletions(-) diff --git a/conanfile.py b/conanfile.py index d6d24c8c0..64d35df54 100644 --- a/conanfile.py +++ b/conanfile.py @@ -9,7 +9,7 @@ class HomestoreConan(ConanFile): name = "homestore" - version = "6.4.55" + version = "6.4.56" homepage = "https://github.com/eBay/Homestore" description = "HomeStore Storage Engine" diff --git a/src/include/homestore/replication/repl_dev.h b/src/include/homestore/replication/repl_dev.h index 9965ada5d..7a52d4e7e 100644 --- a/src/include/homestore/replication/repl_dev.h +++ b/src/include/homestore/replication/repl_dev.h @@ -36,7 +36,8 @@ VENUM(repl_req_state_t, uint32_t, DATA_WRITTEN = 1 << 2, // Data has been written to the storage LOG_RECEIVED = 1 << 3, // Log is received and waiting for data LOG_FLUSHED = 1 << 4, // Log has been flushed - ERRORED = 1 << 5 // Error has happened and cleaned up + ERRORED = 1 << 5, // Error has happened and cleaned up + LAST_STATE // Automatically adjusts to count the number of states ) VENUM(journal_type_t, uint16_t, @@ -125,7 +126,7 @@ struct repl_req_ctx : public boost::intrusive_ref_counter< repl_req_ctx, boost:: friend class SoloReplDev; public: - repl_req_ctx() {} + repl_req_ctx() { m_timestamps[std::bit_width(uint32_cast(repl_req_state_t::INIT))] = Clock::now(); } virtual ~repl_req_ctx(); void init(repl_key rkey, journal_type_t op_code, bool is_proposer, sisl::blob const& user_header, sisl::blob const& key, uint32_t data_size); @@ -156,8 +157,12 @@ struct repl_req_ctx : public boost::intrusive_ref_counter< repl_req_ctx, boost:: /////////////////////// Non modifiers methods ////////////////// std::string to_string() const; std::string to_compact_string() const; - Clock::time_point created_time() const { return m_start_time; } - void set_created_time() { m_start_time = Clock::now(); } + Clock::time_point created_time() const { return ts_of_state(repl_req_state_t::INIT); } + Clock::time_point ts_of_state(repl_req_state_t state) const { + return m_timestamps[std::bit_width(uint32_cast(state))]; + } + uint64_t time_from(repl_req_state_t s) const { return get_elapsed_time_sec(ts_of_state(s)); } + void print_timestamps() const; bool is_expired() const; /////////////////////// All Modifiers methods ////////////////// @@ -221,6 +226,8 @@ struct repl_req_ctx : public boost::intrusive_ref_counter< repl_req_ctx, boost:: std::mutex m_state_mtx; private: + static constexpr int MAX_STATES = std::bit_width(uint32_t(repl_req_state_t::LAST_STATE)); + Clock::time_point m_timestamps[MAX_STATES]; // timestamp of reaching each state repl_key m_rkey; // Unique key for the request sisl::blob m_header; // User header sisl::blob m_key; // User supplied key for this req diff --git a/src/lib/replication/repl_dev/common.cpp b/src/lib/replication/repl_dev/common.cpp index 71927a3ad..6bc5cd09b 100644 --- a/src/lib/replication/repl_dev/common.cpp +++ b/src/lib/replication/repl_dev/common.cpp @@ -146,7 +146,10 @@ bool repl_req_ctx::save_fetched_data(sisl::GenericClientResponse const& fetched_ return true; } -void repl_req_ctx::add_state(repl_req_state_t s) { m_state.fetch_or(uint32_cast(s)); } +void repl_req_ctx::add_state(repl_req_state_t s) { + m_state.fetch_or(uint32_cast(s)); + m_timestamps[std::bit_width(uint32_cast(s))] = Clock::now(); +} bool repl_req_ctx::add_state_if_not_already(repl_req_state_t s) { bool changed{false}; @@ -154,6 +157,7 @@ bool repl_req_ctx::add_state_if_not_already(repl_req_state_t s) { while (!(cur_v & uint32_cast(s))) { if (m_state.compare_exchange_weak(cur_v, cur_v | uint32_cast(s))) { changed = true; + m_timestamps[std::bit_width(uint32_cast(s))] = Clock::now(); break; } } @@ -161,6 +165,15 @@ bool repl_req_ctx::add_state_if_not_already(repl_req_state_t s) { return changed; } +void repl_req_ctx::print_timestamps() const { + for (int i = 0; i < MAX_STATES; i++) { + if (m_timestamps[i] != Clock::time_point()) + std::cout + << "State " << i << " Timestamp " + << std::chrono::duration_cast< std::chrono::milliseconds >(m_timestamps[i] - m_timestamps[0]).count(); + } +} + void repl_req_ctx::clear() { m_header = sisl::blob{}; m_key = sisl::blob{}; @@ -200,7 +213,7 @@ std::string repl_req_ctx::to_compact_string() const { } bool repl_req_ctx::is_expired() const { - return get_elapsed_time_sec(m_start_time) > HS_DYNAMIC_CONFIG(consensus.repl_req_timeout_sec); + return time_from(repl_req_state_t::LOG_RECEIVED) > HS_DYNAMIC_CONFIG(consensus.repl_req_timeout_sec); } } // namespace homestore diff --git a/src/lib/replication/repl_dev/raft_state_machine.cpp b/src/lib/replication/repl_dev/raft_state_machine.cpp index 6e920b997..41e3cfa03 100644 --- a/src/lib/replication/repl_dev/raft_state_machine.cpp +++ b/src/lib/replication/repl_dev/raft_state_machine.cpp @@ -230,8 +230,6 @@ void RaftStateMachine::unlink_lsn_to_req(int64_t lsn) { void RaftStateMachine::link_lsn_to_req(repl_req_ptr_t rreq, int64_t lsn) { rreq->set_lsn(lsn); rreq->add_state(repl_req_state_t::LOG_RECEIVED); - // reset the rreq created_at time to now https://github.com/eBay/HomeStore/issues/506 - rreq->set_created_time(); [[maybe_unused]] auto r = m_lsn_req_map.insert(lsn, std::move(rreq)); RD_DBG_ASSERT_EQ(r.second, true, "lsn={} already in precommit list", lsn); }