Debug log store UT.

eBay · Feb 6, 2024 · 6d95a06 · 6d95a06
1 parent e073fe2
commit 6d95a06
Show file tree

Hide file tree

Showing 3 changed files with 29 additions and 20 deletions.
diff --git a/src/lib/logstore/log_dev.cpp b/src/lib/logstore/log_dev.cpp
@@ -801,18 +801,15 @@ logdev_key LogDev::do_device_truncate(bool dry_run) {
     }
 
     if ((min_safe_ld_key == logdev_key::out_of_bound_ld_key()) || (min_safe_ld_key.idx < 0)) {
-        HS_PERIODIC_LOG(
-            INFO, logstore,
-            "[Logdev={}] No log store append on any log stores, skipping device truncation, all_logstore_info:<{}>",
-            m_logdev_id, dbg_str);
+        LOGINFO("[Logdev={}] No log store append on any log stores, skipping device truncation, all_logstore_info:<{}>",
+                m_logdev_id, dbg_str);
         return min_safe_ld_key;
     }
 
     // Got the safest log id to truncate and actually truncate upto the safe log idx to the log device
     if (!dry_run) { truncate(min_safe_ld_key); }
-    HS_PERIODIC_LOG(INFO, logstore,
-                    "[Logdev={}] LogDevice truncate, all_logstore_info:<{}> safe log dev key to truncate={}",
-                    m_logdev_id, dbg_str, min_safe_ld_key);
+    LOGINFO("[Logdev={}] LogDevice truncate, all_logstore_info:<{}> safe log dev key to truncate={}", m_logdev_id,
+            dbg_str, min_safe_ld_key);
 
     // We call post device truncation only to the log stores whose prepared truncation points are fully
     // truncated or to stores which didn't particpate in this device truncation.
@@ -1055,7 +1052,7 @@ void LogDevMetadata::remove_rollback_record_upto(logid_t upto_id, bool persist_n
     uint32_t n_removed{0};
     for (auto i = m_rollback_sb->num_records; i > 0; --i) {
         auto& rec = m_rollback_sb->at(i - 1);
-        LOGINFO("Removing record sb {} {}", rec.idx_range.second, upto_id);
+        LOGINFO("Removing record sb {}-{} {}", rec.idx_range.first, rec.idx_range.second, upto_id);
         if (rec.idx_range.second <= upto_id) {
             m_rollback_sb->remove_ith_record(i - 1);
             ++n_removed;
@@ -1064,7 +1061,7 @@ void LogDevMetadata::remove_rollback_record_upto(logid_t upto_id, bool persist_n
 
     if (n_removed) {
         for (auto it = m_rollback_info.begin(); it != m_rollback_info.end();) {
-            LOGINFO("Removing info {} {}", it->second.second, upto_id);
+            LOGINFO("Removing info {}-{} {}", it->second.first, it->second.second, upto_id);
             if (it->second.second <= upto_id) {
                 it = m_rollback_info.erase(it);
             } else {

diff --git a/src/lib/logstore/log_store.cpp b/src/lib/logstore/log_store.cpp
@@ -259,16 +259,15 @@ void HomeLogStore::do_truncate(logstore_seq_num_t upto_seq_num) {
     const int ind = search_max_le(upto_seq_num);
     if (ind < 0) {
         // m_safe_truncation_boundary.pending_dev_truncation = false;
-        THIS_LOGSTORE_PERIODIC_LOG(DEBUG,
-                                   "Truncate upto lsn={}, possibly already truncated so ignoring. Current safe device "
-                                   "truncation barrier=<log_id={}>",
-                                   upto_seq_num, m_safe_truncation_boundary.ld_key);
+        LOGINFO("Truncate upto store {} lsn={}, possibly already truncated so ignoring. Current safe device "
+                "truncation barrier=<log_id={}>",
+                m_store_id, upto_seq_num, m_safe_truncation_boundary.ld_key);
         return;
     }
 
-    THIS_LOGSTORE_PERIODIC_LOG(
-        DEBUG, "Truncate upto lsn={}, nearest safe device truncation barrier <ind={} log_id={}>, is_last_barrier={}",
-        upto_seq_num, ind, m_truncation_barriers[ind].ld_key,
+    LOGINFO(
+        "Truncate upto store {} lsn={}, nearest safe device truncation barrier <ind={} log_id={}>, is_last_barrier={}",
+        m_store_id, upto_seq_num, ind, m_truncation_barriers[ind].ld_key,
         (ind == static_cast< int >(m_truncation_barriers.size() - 1)));
 
     m_safe_truncation_boundary.ld_key = m_truncation_barriers[ind].ld_key;

diff --git a/src/tests/test_log_store.cpp b/src/tests/test_log_store.cpp
@@ -682,14 +682,22 @@ class LogStoreTest : public ::testing::Test {
             const auto c_seq_num = lsc->m_log_store->get_contiguous_completed_seq_num(-1);
             if (t_seq_num == c_seq_num) {
                 ++skip_truncation;
+                LOGINFO("Skipping truncation for store {}", lsc->m_log_store->get_store_id());
                 continue;
             }
+            LOGINFO("Before truncation store store {} truncated_upto {} completed_seq_num {} ",
+                    lsc->m_log_store->get_store_id(), lsc->m_log_store->truncated_upto(),
+                    lsc->m_log_store->get_contiguous_completed_seq_num(-1));
             lsc->truncate(lsc->m_log_store->get_contiguous_completed_seq_num(-1));
             lsc->read_validate();
+            LOGINFO("After truncation store store {} truncated_upto {} completed_seq_num {} ",
+                    lsc->m_log_store->get_store_id(), lsc->m_log_store->truncated_upto(),
+                    lsc->m_log_store->get_contiguous_completed_seq_num(-1));
         }
 
         if (skip_truncation) {
             /* not needed to call device truncate as one log store is not truncated */
+            LOGINFO("Skip device truncation");
             return;
         }
 
@@ -755,7 +763,12 @@ class LogStoreTest : public ::testing::Test {
         }
     }
 
-    void rollback_validate(uint32_t num_lsns_to_rollback) { pick_log_store()->rollback_validate(num_lsns_to_rollback); }
+    void rollback_validate(uint32_t num_lsns_to_rollback, int32_t store_client = -1) {
+        auto lsc = pick_log_store();
+        if (store_client != -1) { lsc = SampleDB::instance().m_log_store_clients[store_client].get(); }
+
+        lsc->rollback_validate(num_lsns_to_rollback);
+    }
 
     void post_truncate_rollback_validate() {
         for (size_t i{0}; i < SampleDB::instance().m_log_store_clients.size(); ++i) {
@@ -1153,15 +1166,15 @@ TEST_F(LogStoreTest, Rollback) {
     this->wait_for_inserts();
 
     LOGINFO("Step 4: Rollback last 50 entries and validate if pre-rollback entries are intact");
-    this->rollback_validate(50); // Last entry = 450
+    this->rollback_validate(50, 1); // Last entry = 450, Store 1
 
     LOGINFO("Step 5: Append 25 entries after rollback is completed");
     this->init(25, {std::make_pair(1ull, 100)});
     this->kickstart_inserts(1, 10);
     this->wait_for_inserts(); // Last entry = 475
 
     LOGINFO("Step 7: Rollback again for 75 entries even before previous rollback entry");
-    this->rollback_validate(75); // Last entry = 400
+    this->rollback_validate(75, 1); // Last entry = 400
 
     LOGINFO("Step 8: Append 25 entries after second rollback is completed");
     this->init(25, {std::make_pair(1ull, 100)});
@@ -1178,7 +1191,7 @@ TEST_F(LogStoreTest, Rollback) {
     this->wait_for_inserts(); // Last entry = 450
 
     LOGINFO("Step 11: Rollback again for 75 entries even before previous rollback entry");
-    this->rollback_validate(75); // Last entry = 375
+    this->rollback_validate(75, 1); // Last entry = 375
 
     LOGINFO("Step 12: After 3rd rollback, append another 25 entries");
     this->init(25, {std::make_pair(1ull, 100)});