From f1be515503cda4692c6f52f02c52fbc235cba403 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 ca31ef1b6..c31e269b7 100644 --- a/conanfile.py +++ b/conanfile.py @@ -9,7 +9,7 @@ class HomestoreConan(ConanFile): name = "homestore" - version = "6.4.49" + version = "6.4.50" 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 5d1a0e8c2..1cf2e1bde 100644 --- a/src/include/homestore/replication/repl_dev.h +++ b/src/include/homestore/replication/repl_dev.h @@ -34,7 +34,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, @@ -121,7 +122,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); @@ -153,8 +154,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 ////////////////// @@ -217,6 +222,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 47947cd7c..38d8f54a7 100644 --- a/src/lib/replication/repl_dev/common.cpp +++ b/src/lib/replication/repl_dev/common.cpp @@ -145,7 +145,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}; @@ -153,6 +156,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; } } @@ -160,6 +164,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{}; @@ -199,7 +212,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 12a9be312..92ae90b46 100644 --- a/src/lib/replication/repl_dev/raft_state_machine.cpp +++ b/src/lib/replication/repl_dev/raft_state_machine.cpp @@ -222,8 +222,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); }