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 <[email protected]>

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"

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

src/lib/replication/repl_dev/common.cpp

@@ -146,21 +146,34 @@ 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};
     auto cur_v = m_state.load();
     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;
         }
     }
 
     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

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);
 }