Import wiredtiger: f733d398ba9fbc9802de885912c8d3f34bc6cf62 from branch mongodb-master

ref: 6ddfc52f11..f733d398ba
for: 5.2.0

WT-8284       Improve verbose logging for transactions when rollback is required

4 files changed, 41 insertions, 3 deletions

diff --git a/src/third_party/wiredtiger/import.data b/src/third_party/wiredtiger/import.data
index e83685a837b..481b22f9b4d 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": "6ddfc52f11222bcd47518fce6b5ed458075f9c31"
+    "commit": "f733d398ba9fbc9802de885912c8d3f34bc6cf62"
 }
diff --git a/src/third_party/wiredtiger/src/evict/evict_lru.c b/src/third_party/wiredtiger/src/evict/evict_lru.c
index 0bfaf1c9f33..d50e6378254 100644
--- a/src/third_party/wiredtiger/src/evict/evict_lru.c
+++ b/src/third_party/wiredtiger/src/evict/evict_lru.c
@@ -2383,6 +2383,8 @@ __wt_cache_eviction_worker(WT_SESSION_IMPL *session, bool busy, bool readonly, d
         if (!F_ISSET(conn, WT_CONN_RECOVERING) && __wt_cache_stuck(session)) {
             ret = __wt_txn_is_blocking(session);
             if (ret == WT_ROLLBACK) {
+                __wt_verbose_debug(
+                  session, WT_VERB_TRANSACTION, "Rollback reason: %s", "Cache full");
                 --cache->evict_aggressive_score;
                 WT_STAT_CONN_INCR(session, txn_fail_cache);
                 if (app_thread)
diff --git a/src/third_party/wiredtiger/src/include/txn_inline.h b/src/third_party/wiredtiger/src/include/txn_inline.h
index f1d0a9f5dcd..1201ff5326d 100644
--- a/src/third_party/wiredtiger/src/include/txn_inline.h
+++ b/src/third_party/wiredtiger/src/include/txn_inline.h
@@ -1312,10 +1312,13 @@ static inline int
 __wt_txn_modify_check(
   WT_SESSION_IMPL *session, WT_CURSOR_BTREE *cbt, WT_UPDATE *upd, wt_timestamp_t *prev_tsp)
 {
+    WT_DECL_ITEM(buf);
     WT_DECL_RET;
     WT_TIME_WINDOW tw;
     WT_TXN *txn;
     WT_TXN_GLOBAL *txn_global;
+    uint32_t snap_count;
+    char ts_string[WT_TS_INT_STRING_SIZE];
     bool ignore_prepare_set, rollback, tw_found;
 
     rollback = tw_found = false;
@@ -1337,6 +1340,9 @@ __wt_txn_modify_check(
     F_CLR(txn, WT_TXN_IGNORE_PREPARE);
     for (; upd != NULL && !__wt_txn_upd_visible(session, upd); upd = upd->next) {
         if (upd->txnid != WT_TXN_ABORTED) {
+            __wt_verbose_debug(session, WT_VERB_TRANSACTION,
+              "Conflict with update with txn id %" PRIu64 " at timestamp: %s", upd->txnid,
+              __wt_timestamp_to_string(upd->start_ts, ts_string));
             rollback = true;
             break;
         }
@@ -1352,14 +1358,39 @@ __wt_txn_modify_check(
     if (!rollback && upd == NULL) {
         __wt_read_cell_time_window(cbt, &tw, &tw_found);
         if (tw_found) {
-            if (WT_TIME_WINDOW_HAS_STOP(&tw))
+            if (WT_TIME_WINDOW_HAS_STOP(&tw)) {
                 rollback = !__wt_txn_tw_stop_visible(session, &tw);
-            else
+                if (rollback)
+                    __wt_verbose_debug(session, WT_VERB_TRANSACTION,
+                      "Conflict with update %" PRIu64 " at stop timestamp: %s", tw.stop_txn,
+                      __wt_timestamp_to_string(tw.stop_ts, ts_string));
+            } else {
                 rollback = !__wt_txn_tw_start_visible(session, &tw);
+                if (rollback)
+                    __wt_verbose_debug(session, WT_VERB_TRANSACTION,
+                      "Conflict with update %" PRIu64 " at start timestamp: %s", tw.start_txn,
+                      __wt_timestamp_to_string(tw.start_ts, ts_string));
+            }
         }
     }
 
     if (rollback) {
+        /* Dump information about the txn snapshot. */
+        if (WT_VERBOSE_LEVEL_ISSET(session, WT_VERB_TRANSACTION, WT_VERBOSE_DEBUG)) {
+            WT_ERR(__wt_scr_alloc(session, 1024, &buf));
+            WT_ERR(__wt_buf_fmt(session, buf,
+              "snapshot_min=%" PRIu64 ", snapshot_max=%" PRIu64 ", snapshot_count=%" PRIu32,
+              txn->snap_min, txn->snap_max, txn->snapshot_count));
+            if (txn->snapshot_count > 0) {
+                WT_ERR(__wt_buf_catfmt(session, buf, ", snapshots=["));
+                for (snap_count = 0; snap_count < txn->snapshot_count - 1; ++snap_count)
+                    WT_ERR(
+                      __wt_buf_catfmt(session, buf, "%" PRIu64 ",", txn->snapshot[snap_count]));
+                WT_ERR(__wt_buf_catfmt(session, buf, "%" PRIu64 "]", txn->snapshot[snap_count]));
+            }
+            __wt_verbose_debug(session, WT_VERB_TRANSACTION, "%s", (const char *)buf->data);
+        }
+
         WT_STAT_CONN_DATA_INCR(session, txn_update_conflict);
         ret = __wt_txn_rollback_required(session, "conflict between concurrent operations");
     }
@@ -1380,8 +1411,12 @@ __wt_txn_modify_check(
         } else if (tw_found)
             *prev_tsp = WT_TIME_WINDOW_HAS_STOP(&tw) ? tw.durable_stop_ts : tw.durable_start_ts;
     }
+
     if (ignore_prepare_set)
         F_SET(txn, WT_TXN_IGNORE_PREPARE);
+
+err:
+    __wt_scr_free(session, &buf);
     return (ret);
 }
 
diff --git a/src/third_party/wiredtiger/src/txn/txn.c b/src/third_party/wiredtiger/src/txn/txn.c
index 2ad2033ba4b..bddfbe26ac7 100644
--- a/src/third_party/wiredtiger/src/txn/txn.c
+++ b/src/third_party/wiredtiger/src/txn/txn.c
@@ -2212,6 +2212,7 @@ int
 __wt_txn_rollback_required(WT_SESSION_IMPL *session, const char *reason)
 {
     session->txn->rollback_reason = reason;
+    __wt_verbose_debug(session, WT_VERB_TRANSACTION, "Rollback reason: %s", reason);
     return (WT_ROLLBACK);
 }