From 3463566d3fb6f9bd68c8fb6b1387417faa09128b Mon Sep 17 00:00:00 2001 From: Chenhao Qu Date: Wed, 2 Nov 2022 11:57:20 +1100 Subject: Import wiredtiger: 2c683e1b5159958d4564f442225e3fc0466658cc from branch mongodb-master ref: 8e8d4be313..2c683e1b51 for: 6.2.0-rc0 WT-10025 Improve RTS logs --- .../wiredtiger/src/txn/txn_rollback_to_stable.c | 82 ++++++++++++++-------- 1 file changed, 53 insertions(+), 29 deletions(-) (limited to 'src/third_party/wiredtiger/src/txn') 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), -- cgit v1.2.1