Import wiredtiger: 2c683e1b5159958d4564f442225e3fc0466658cc from branch mongodb-master

ref: 8e8d4be313..2c683e1b51
for: 6.2.0-rc0

WT-10025 Improve RTS logs

2 files changed, 54 insertions, 30 deletions

diff --git a/src/third_party/wiredtiger/import.data b/src/third_party/wiredtiger/import.data
index 4058cab8ee0..34512cbf7ba 100644
--- a/src/third_party/wiredtiger/import.data
+++ b/src/third_party/wiredtiger/import.data
@@ -2,5 +2,5 @@
     "vendor": "wiredtiger",
     "github": "wiredtiger/wiredtiger.git",
     "branch": "mongodb-master",
-    "commit": "8e8d4be3138eba73b4d530b832dcf2cc545e2a64"
+    "commit": "2c683e1b5159958d4564f442225e3fc0466658cc"
 }
diff --git a/src/third_party/wiredtiger/src/txn/txn_rollback_to_stable.c b/src/third_party/wiredtiger/src/txn/txn_rollback_to_stable.c
index 749a626d9bd..b9b2436cf31 100644
--- a/src/third_party/wiredtiger/src/txn/txn_rollback_to_stable.c
+++ b/src/third_party/wiredtiger/src/txn/txn_rollback_to_stable.c
@@ -94,8 +94,10 @@ __rollback_abort_update(WT_SESSION_IMPL *session, WT_ITEM *key, WT_UPDATE *first
 {
     WT_UPDATE *stable_upd, *tombstone, *upd;
     char ts_string[2][WT_TS_INT_STRING_SIZE];
+    bool txn_id_visible;
 
     stable_upd = tombstone = NULL;
+    txn_id_visible = false;
     if (stable_update_found != NULL)
         *stable_update_found = false;
     for (upd = first_upd; upd != NULL; upd = upd->next) {
@@ -114,14 +116,18 @@ __rollback_abort_update(WT_SESSION_IMPL *session, WT_ITEM *key, WT_UPDATE *first
          * of the rollback to stable page read, it instantiates the tombstones on the page.
          * The transaction id validation is ignored in all scenarios except recovery.
          */
-        if (!__rollback_txn_visible_id(session, upd->txnid) ||
-          rollback_timestamp < upd->durable_ts || upd->prepare_state == WT_PREPARE_INPROGRESS) {
+        txn_id_visible = __rollback_txn_visible_id(session, upd->txnid);
+        if (!txn_id_visible || rollback_timestamp < upd->durable_ts ||
+          upd->prepare_state == WT_PREPARE_INPROGRESS) {
             __wt_verbose_multi(session, WT_VERB_RECOVERY_RTS(session),
               "rollback to stable update aborted with txnid: %" PRIu64
-              " durable timestamp: %s and stable timestamp: %s, prepared: %s",
-              upd->txnid, __wt_timestamp_to_string(upd->durable_ts, ts_string[0]),
+              ", txnid not visible: %s, or stable timestamp (%s) < durable timestamp (%s): %s, or "
+              "prepare state (%d) is in progress: %s",
+              upd->txnid, !txn_id_visible ? "true" : "false",
               __wt_timestamp_to_string(rollback_timestamp, ts_string[1]),
-              rollback_timestamp < upd->durable_ts ? "false" : "true");
+              __wt_timestamp_to_string(upd->durable_ts, ts_string[0]),
+              rollback_timestamp < upd->durable_ts ? "true" : "false", upd->prepare_state,
+              upd->prepare_state == WT_PREPARE_INPROGRESS ? "true" : "false");
 
             upd->txnid = WT_TXN_ABORTED;
             WT_STAT_CONN_INCR(session, txn_rts_upd_aborted);
@@ -577,7 +583,7 @@ __rollback_ondisk_fixup_key(WT_SESSION_IMPL *session, WT_REF *ref, WT_ROW *rip,
         upd->durable_ts = hs_tw->durable_start_ts;
         upd->start_ts = hs_tw->start_ts;
         __wt_verbose_multi(session, WT_VERB_RECOVERY_RTS(session),
-          "update restored from history store txnid: %" PRIu64 ", start_ts: %s and durable_ts: %s",
+          "history store update restored txnid: %" PRIu64 ", start_ts: %s and durable_ts: %s",
           upd->txnid, __wt_timestamp_to_string(upd->start_ts, ts_string[0]),
           __wt_timestamp_to_string(upd->durable_ts, ts_string[1]));
 
@@ -616,8 +622,8 @@ __rollback_ondisk_fixup_key(WT_SESSION_IMPL *session, WT_REF *ref, WT_ROW *rip,
             tombstone->durable_ts = hs_tw->durable_stop_ts;
             tombstone->start_ts = hs_tw->stop_ts;
             __wt_verbose_multi(session, WT_VERB_RECOVERY_RTS(session),
-              "tombstone restored from history store txnid: %" PRIu64
-              ", start_ts: %s, durable_ts: %s",
+              "history store tombstone restored txnid: %" PRIu64
+              ", start_ts: %s and durable_ts: %s",
               tombstone->txnid, __wt_timestamp_to_string(tombstone->start_ts, ts_string[0]),
               __wt_timestamp_to_string(tombstone->durable_ts, ts_string[1]));
 
@@ -684,6 +690,7 @@ __rollback_abort_ondisk_kv(WT_SESSION_IMPL *session, WT_REF *ref, WT_ROW *rip, u
     WT_PAGE *page;
     WT_UPDATE *upd;
     uint8_t *memp;
+    char time_string[WT_TIME_STRING_SIZE];
     char ts_string[5][WT_TS_INT_STRING_SIZE];
     bool prepared;
 
@@ -703,8 +710,8 @@ __rollback_abort_ondisk_kv(WT_SESSION_IMPL *session, WT_REF *ref, WT_ROW *rip, u
          */
         if (vpack->tw.durable_stop_ts > rollback_timestamp || vpack->tw.stop_ts == WT_TS_MAX) {
             __wt_verbose_multi(session, WT_VERB_RECOVERY_RTS(session),
-              "hs update aborted with start durable/commit timestamp: %s, %s, stop durable/commit "
-              "timestamp: %s, %s and stable timestamp: %s",
+              "history store update aborted with start durable/commit timestamp: %s, %s, stop "
+              "durable/commit timestamp: %s, %s and stable timestamp: %s",
               __wt_timestamp_to_string(vpack->tw.durable_start_ts, ts_string[0]),
               __wt_timestamp_to_string(vpack->tw.start_ts, ts_string[1]),
               __wt_timestamp_to_string(vpack->tw.durable_stop_ts, ts_string[2]),
@@ -718,11 +725,13 @@ __rollback_abort_ondisk_kv(WT_SESSION_IMPL *session, WT_REF *ref, WT_ROW *rip, u
       !__rollback_txn_visible_id(session, vpack->tw.start_txn) ||
       (!WT_TIME_WINDOW_HAS_STOP(&vpack->tw) && prepared)) {
         __wt_verbose_multi(session, WT_VERB_RECOVERY_RTS(session),
-          "on-disk update aborted with start durable timestamp: %s, commit timestamp: %s, "
-          "prepared: %s, stable timestamp: %s and txnid : %" PRIu64,
-          __wt_timestamp_to_string(vpack->tw.durable_start_ts, ts_string[0]),
-          __wt_timestamp_to_string(vpack->tw.start_ts, ts_string[1]), prepared ? "true" : "false",
-          __wt_timestamp_to_string(rollback_timestamp, ts_string[2]), vpack->tw.start_txn);
+          "on-disk update aborted with time window %s. Start durable timestamp > stable timestamp: "
+          "%s, or txnid is not visible: %s, or tw has not stop and is prepared: %s",
+          __wt_time_point_to_string(
+            vpack->tw.start_ts, vpack->tw.durable_start_ts, vpack->tw.start_txn, time_string),
+          vpack->tw.durable_start_ts > rollback_timestamp ? "true" : "false",
+          !__rollback_txn_visible_id(session, vpack->tw.start_txn) ? "true" : "false",
+          !WT_TIME_WINDOW_HAS_STOP(&vpack->tw) && prepared ? "true" : "false");
         if (!F_ISSET(S2C(session), WT_CONN_IN_MEMORY))
             return (__rollback_ondisk_fixup_key(
               session, ref, rip, recno, row_key, vpack, rollback_timestamp));
@@ -1231,6 +1240,7 @@ static int
 __rollback_abort_updates(WT_SESSION_IMPL *session, WT_REF *ref, wt_timestamp_t rollback_timestamp)
 {
     WT_PAGE *page;
+    bool modified;
 
     /*
      * If we have a ref with clean page, find out whether the page has any modifications that are
@@ -1238,16 +1248,16 @@ __rollback_abort_updates(WT_SESSION_IMPL *session, WT_REF *ref, wt_timestamp_t r
      * page may also contain modifications that need rollback.
      */
     page = ref->page;
-    if (!__wt_page_is_modified(page) &&
-      !__rollback_page_needs_abort(session, ref, rollback_timestamp)) {
-        __wt_verbose_multi(session, WT_VERB_RECOVERY_RTS(session), "%p: page skipped", (void *)ref);
+    modified = __wt_page_is_modified(page);
+    if (!modified && !__rollback_page_needs_abort(session, ref, rollback_timestamp)) {
+        __wt_verbose_multi(session, WT_VERB_RECOVERY_RTS(session),
+          "%p: unmodified stable page skipped", (void *)ref);
         return (0);
     }
 
     WT_STAT_CONN_INCR(session, txn_rts_pages_visited);
-    __wt_verbose_multi(session, WT_VERB_RECOVERY_RTS(session),
-      "%p: page rolled back when page is modified: %s", (void *)ref,
-      __wt_page_is_modified(page) ? "true" : "false");
+    __wt_verbose_multi(session, WT_VERB_RECOVERY_RTS(session), "%p: roll back %s page", (void *)ref,
+      modified ? "modified" : "clean");
 
     switch (page->type) {
     case WT_PAGE_COL_FIX:
@@ -1284,6 +1294,7 @@ __rollback_to_stable_page_skip(
 {
     WT_PAGE_DELETED *page_del;
     wt_timestamp_t rollback_timestamp;
+    char time_string[WT_TIME_STRING_SIZE];
 
     rollback_timestamp = *(wt_timestamp_t *)context;
     WT_UNUSED(visible_all);
@@ -1313,8 +1324,15 @@ __rollback_to_stable_page_skip(
               page_del == NULL || page_del->prepare_state == WT_PREPARE_INIT ||
                 page_del->prepare_state == WT_PREPARE_RESOLVED);
 
-            __wt_verbose_multi(
-              session, WT_VERB_RECOVERY_RTS(session), "%p: deleted page walk skipped", (void *)ref);
+            if (page_del == NULL)
+                __wt_verbose_multi(session, WT_VERB_RECOVERY_RTS(session),
+                  "%p: deleted page walk skipped", (void *)ref);
+            else {
+                __wt_verbose_multi(session, WT_VERB_RECOVERY_RTS(session),
+                  "%p: deleted page walk skipped page_del %s", (void *)ref,
+                  __wt_time_point_to_string(page_del->timestamp, page_del->durable_timestamp,
+                    page_del->txnid, time_string));
+            }
             WT_STAT_CONN_INCR(session, txn_rts_tree_walk_skip_pages);
             *skipp = true;
         }
@@ -1335,7 +1353,7 @@ __rollback_to_stable_page_skip(
     if (!__rollback_page_needs_abort(session, ref, rollback_timestamp)) {
         *skipp = true;
         __wt_verbose_multi(
-          session, WT_VERB_RECOVERY_RTS(session), "%p: page walk skipped", (void *)ref);
+          session, WT_VERB_RECOVERY_RTS(session), "%p: stable page walk skipped", (void *)ref);
         WT_STAT_CONN_INCR(session, txn_rts_tree_walk_skip_pages);
     }
 
@@ -1782,13 +1800,19 @@ __rollback_to_stable_btree_apply(
         dhandle_allocated = true;
 
         __wt_verbose_multi(session, WT_VERB_RECOVERY_RTS(session),
-          "tree rolled back with durable timestamp: %s, or when tree is modified: %s or "
-          "prepared updates: %s or when durable time is not found: %s or txnid: %" PRIu64
-          " is greater than recovery checkpoint snap min: %s",
+          "tree rolled back because it is modified: %s, or its durable timestamp (%s) > stable "
+          "timestamp (%s): "
+          "%s, or it has prepared updates: %s, or durable "
+          "timestamp is not found: %s, or txnid (%" PRIu64
+          ") > recovery checkpoint snap min (%" PRIu64 "): %s",
+          S2BT(session)->modified ? "true" : "false",
           __wt_timestamp_to_string(max_durable_ts, ts_string[0]),
-          S2BT(session)->modified ? "true" : "false", prepared_updates ? "true" : "false",
-          !durable_ts_found ? "true" : "false", rollback_txnid,
+          __wt_timestamp_to_string(rollback_timestamp, ts_string[1]),
+          max_durable_ts > rollback_timestamp ? "true" : "false",
+          prepared_updates ? "true" : "false", !durable_ts_found ? "true" : "false", rollback_txnid,
+          S2C(session)->recovery_ckpt_snap_min,
           has_txn_updates_gt_than_ckpt_snap ? "true" : "false");
+
         WT_ERR(__rollback_to_stable_btree(session, rollback_timestamp));
     } else
         __wt_verbose_multi(session, WT_VERB_RECOVERY_RTS(session),