Import wiredtiger: fbae1a2989c947f4f8d17ac433e93edf85251900 from branch mongodb-6.1

ref: 84ea010e09..fbae1a2989
for: 6.1.0-rc1

WT-9797 Add more trace messages to test format. (#8232)

4 files changed, 35 insertions, 15 deletions

diff --git a/src/third_party/wiredtiger/import.data b/src/third_party/wiredtiger/import.data
index a383a4edcb1..deb397bb13c 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-6.1",
-    "commit": "84ea010e09c6079b2d6d98d7b1ab97075115e70a"
+    "commit": "fbae1a2989c947f4f8d17ac433e93edf85251900"
 }
diff --git a/src/third_party/wiredtiger/test/format/backup.c b/src/third_party/wiredtiger/test/format/backup.c
index 714b4b722af..722bfdedc3f 100644
--- a/src/third_party/wiredtiger/test/format/backup.c
+++ b/src/third_party/wiredtiger/test/format/backup.c
@@ -249,6 +249,9 @@ copy_blocks(WT_SESSION *session, WT_CURSOR *bkup_c, const char *name)
     while ((ret = incr_cur->next(incr_cur)) == 0) {
         testutil_check(incr_cur->get_key(incr_cur, &offset, &size, &type));
         if (type == WT_BACKUP_RANGE) {
+            trace_msg(session,
+              "Backup file %s type WT_BACKUP_RANGE offset %" PRIu64 " length %" PRIu64, name,
+              offset, size);
             /*
              * Since we are using system calls below instead of a WiredTiger function, we have to
              * prepend the home directory to the file names ourselves.
@@ -311,6 +314,7 @@ copy_blocks(WT_SESSION *session, WT_CURSOR *bkup_c, const char *name)
             testutil_assert(first_pass == true);
             testutil_assert(rfd == -1);
 
+            trace_msg(session, "Backup file %s type WT_BACKUP_FILE", name);
             /*
              * These operations are using a WiredTiger function so it will prepend the home
              * directory to the name for us.
@@ -466,7 +470,7 @@ backup(void *arg)
     WT_CURSOR *backup_cursor;
     WT_DECL_RET;
     WT_SESSION *session;
-    u_int counter, incremental, period;
+    u_int counter, incremental, num_yield, period;
     uint64_t src_id, this_id;
     const char *config, *key;
     char cfg[512];
@@ -586,14 +590,19 @@ backup(void *arg)
         else
             trace_msg(session, "Backup #%u start: (%s)", ++counter, config);
 
+        num_yield = 0;
         while (
-          (ret = session->open_cursor(session, "backup:", NULL, config, &backup_cursor)) == EBUSY)
+          (ret = session->open_cursor(session, "backup:", NULL, config, &backup_cursor)) == EBUSY) {
+            ++num_yield;
             __wt_yield();
+        }
         if (ret != 0)
             testutil_die(ret, "session.open_cursor: backup");
+        trace_msg(session, "Backup #%u cursor opened. Yielded %u times", counter, num_yield);
 
         while ((ret = backup_cursor->next(backup_cursor)) == 0) {
             testutil_check(backup_cursor->get_key(backup_cursor, &key));
+            trace_msg(session, "Backup #%u copy file %s start", counter, key);
             if (g.backup_incr_flag == INCREMENTAL_BLOCK) {
                 if (full)
                     testutil_copy_file(session, key);
@@ -602,6 +611,7 @@ backup(void *arg)
 
             } else
                 testutil_copy_file(session, key);
+            trace_msg(session, "Backup #%u copy file %s stop", counter, key);
             active_files_add(active_now, key);
         }
         if (ret != WT_NOTFOUND)
@@ -612,8 +622,11 @@ backup(void *arg)
             testutil_check(session->truncate(session, "log:", backup_cursor, NULL, NULL));
 
         testutil_check(backup_cursor->close(backup_cursor));
-        trace_msg(session, "Backup #%u stop%s%s%s", counter, config == NULL ? "" : ": (",
-          config == NULL ? "" : config, config == NULL ? "" : ")");
+        if (config == NULL)
+            trace_msg(session, "Backup #%u stop", counter);
+        else
+            trace_msg(session, "Backup #%u stop: (%s)", counter, config);
+
         lock_writeunlock(session, &g.backup_lock);
         active_files_sort(active_now);
         active_files_remove_missing(active_prev, active_now);
diff --git a/src/third_party/wiredtiger/test/format/checkpoint.c b/src/third_party/wiredtiger/test/format/checkpoint.c
index ac44c2df019..7b63eaba648 100644
--- a/src/third_party/wiredtiger/test/format/checkpoint.c
+++ b/src/third_party/wiredtiger/test/format/checkpoint.c
@@ -125,12 +125,17 @@ checkpoint(void *arg)
                 break;
             }
 
-        trace_msg(session, "Checkpoint #%u start%s%s%s", ++counter,
-          ckpt_config == NULL ? "" : ": (", ckpt_config == NULL ? "" : ckpt_config,
-          ckpt_config == NULL ? "" : ")");
+        if (ckpt_config == NULL)
+            trace_msg(session, "Checkpoint #%u start", ++counter);
+        else
+            trace_msg(session, "Checkpoint #%u start (%s)", ++counter, ckpt_config);
+
         testutil_check(session->checkpoint(session, ckpt_config));
-        trace_msg(session, "Checkpoint #%u stop%s%s%s", counter, ckpt_config == NULL ? "" : ": (",
-          ckpt_config == NULL ? "" : ckpt_config, ckpt_config == NULL ? "" : ")");
+
+        if (ckpt_config == NULL)
+            trace_msg(session, "Checkpoint #%u stop", counter);
+        else
+            trace_msg(session, "Checkpoint #%u stop (%s)", counter, ckpt_config);
 
         if (backup_locked)
             lock_writeunlock(session, &g.backup_lock);
diff --git a/src/third_party/wiredtiger/test/format/ops.c b/src/third_party/wiredtiger/test/format/ops.c
index f2a6d89559d..fa45f9c2caf 100644
--- a/src/third_party/wiredtiger/test/format/ops.c
+++ b/src/third_party/wiredtiger/test/format/ops.c
@@ -1544,14 +1544,15 @@ row_truncate(TINFO *tinfo)
     /* The code assumes we're never truncating the entire object, assert that fact. */
     testutil_assert(tinfo->keyno != 0 || tinfo->last != 0);
 
+    trace_op(tinfo, "truncate %" PRIu64 "-%" PRIu64 " start", tinfo->keyno, tinfo->last);
     if (tinfo->keyno == 0) {
         key_gen(tinfo->table, tinfo->key, tinfo->last);
         cursor->set_key(cursor, tinfo->key);
-        WT_RET(session->truncate(session, NULL, NULL, cursor, NULL));
+        WT_ERR(session->truncate(session, NULL, NULL, cursor, NULL));
     } else if (tinfo->last == 0) {
         key_gen(tinfo->table, tinfo->key, tinfo->keyno);
         cursor->set_key(cursor, tinfo->key);
-        WT_RET(session->truncate(session, NULL, cursor, NULL, NULL));
+        WT_ERR(session->truncate(session, NULL, cursor, NULL, NULL));
     } else {
         key_gen(tinfo->table, tinfo->key, tinfo->keyno);
         cursor->set_key(cursor, tinfo->key);
@@ -1562,12 +1563,13 @@ row_truncate(TINFO *tinfo)
 
         ret = session->truncate(session, NULL, cursor, c2, NULL);
         testutil_check(c2->close(c2));
-        WT_RET(ret);
+        WT_ERR(ret);
     }
 
-    trace_op(tinfo, "truncate %" PRIu64 "-%" PRIu64, tinfo->keyno, tinfo->last);
+err:
+    trace_op(tinfo, "truncate %" PRIu64 "-%" PRIu64 " stop ret %d", tinfo->keyno, tinfo->last, ret);
 
-    return (0);
+    return (ret);
 }
 
 /*