diff --git a/berkdb/txn/txn_rec.c b/berkdb/txn/txn_rec.c index 952a41df43..b20489ccd2 100644 --- a/berkdb/txn/txn_rec.c +++ b/berkdb/txn/txn_rec.c @@ -224,10 +224,21 @@ __txn_dist_commit_recover(dbenv, dbtp, lsnp, op, info) * so we treat this as an abort even if it was a commit record. */ - if (commit_lsn_map && (ret = __txn_commit_map_remove(dbenv, argp->txnid->utxnid))) { - logmsg(LOGMSG_ERROR, "%s: Failed to remove %"PRIu64" from the commit map\n", __func__, - argp->txnid->utxnid); - goto quiet_err; + if (commit_lsn_map) { + ret = __txn_commit_map_remove(dbenv, argp->txnid->utxnid); + if (ret == DB_NOTFOUND) { + /* + * Benign: the commit-LSN map is a windowed cache and need + * not contain every committed txn the backward pass undoes + * (log-file pruning, rebuild-from-checkpoint on restart, + * physrep rewinds). Nothing to un-track; continue the pass. + */ + ret = 0; + } else if (ret != 0) { + logmsg(LOGMSG_ERROR, "%s: Failed to remove %"PRIu64" from the commit map\n", __func__, + argp->txnid->utxnid); + goto quiet_err; + } } ret = __db_txnlist_update(dbenv, @@ -481,10 +492,21 @@ __txn_regop_gen_recover(dbenv, dbtp, lsnp, op, info) (!IS_ZERO_LSN(headp->trunc_lsn) && log_compare(&headp->trunc_lsn, lsnp) < 0)) { - if (commit_lsn_map && (ret = __txn_commit_map_remove(dbenv, argp->txnid->utxnid))) { - logmsg(LOGMSG_ERROR, "%s: Failed to remove %"PRIu64" from the commit map\n", __func__, - argp->txnid->utxnid); - goto quiet_err; + if (commit_lsn_map) { + ret = __txn_commit_map_remove(dbenv, argp->txnid->utxnid); + if (ret == DB_NOTFOUND) { + /* + * Benign: the commit-LSN map is a windowed cache and need + * not contain every committed txn the backward pass undoes + * (log-file pruning, rebuild-from-checkpoint on restart, + * physrep rewinds). Nothing to un-track; continue the pass. + */ + ret = 0; + } else if (ret != 0) { + logmsg(LOGMSG_ERROR, "%s: Failed to remove %"PRIu64" from the commit map\n", __func__, + argp->txnid->utxnid); + goto quiet_err; + } } /* @@ -606,10 +628,21 @@ __txn_regop_recover(dbenv, dbtp, lsnp, op, info) * so we treat this as an abort even if it was a commit record. */ - if (commit_lsn_map && (ret = __txn_commit_map_remove(dbenv, argp->txnid->utxnid))) { - logmsg(LOGMSG_ERROR, "%s: Failed to remove %"PRIu64" from the commit map\n", __func__, - argp->txnid->utxnid); - goto quiet_err; + if (commit_lsn_map) { + ret = __txn_commit_map_remove(dbenv, argp->txnid->utxnid); + if (ret == DB_NOTFOUND) { + /* + * Benign: the commit-LSN map is a windowed cache and need + * not contain every committed txn the backward pass undoes + * (log-file pruning, rebuild-from-checkpoint on restart, + * physrep rewinds). Nothing to un-track; continue the pass. + */ + ret = 0; + } else if (ret != 0) { + logmsg(LOGMSG_ERROR, "%s: Failed to remove %"PRIu64" from the commit map\n", __func__, + argp->txnid->utxnid); + goto quiet_err; + } } ret = __db_txnlist_update(dbenv, @@ -838,10 +871,21 @@ __txn_regop_rowlocks_recover(dbenv, dbtp, lsnp, op, info) __txn_deallocate_ltrans(dbenv, lt); } - if (commit_lsn_map && (ret = __txn_commit_map_remove(dbenv, argp->txnid->utxnid))) { - logmsg(LOGMSG_ERROR, "%s: Failed to remove %"PRIu64" from the commit map\n", __func__, - argp->txnid->utxnid); - goto quiet_err; + if (commit_lsn_map) { + ret = __txn_commit_map_remove(dbenv, argp->txnid->utxnid); + if (ret == DB_NOTFOUND) { + /* + * Benign: the commit-LSN map is a windowed cache and need + * not contain every committed txn the backward pass undoes + * (log-file pruning, rebuild-from-checkpoint on restart, + * physrep rewinds). Nothing to un-track; continue the pass. + */ + ret = 0; + } else if (ret != 0) { + logmsg(LOGMSG_ERROR, "%s: Failed to remove %"PRIu64" from the commit map\n", __func__, + argp->txnid->utxnid); + goto quiet_err; + } } /* diff --git a/berkdb/txn/txn_util.c b/berkdb/txn/txn_util.c index 778785cb71..6cbd477272 100644 --- a/berkdb/txn/txn_util.c +++ b/berkdb/txn/txn_util.c @@ -40,6 +40,15 @@ int dist_txn_abort_write_blkseq(void *bdb_state, void *bskey, int bskeylen); extern int set_commit_context_prepared(unsigned long long context); extern int gbl_utxnid_log; +/* + * Count of times we were asked to remove a utxnid that wasn't present in the + * commit-LSN map. This is an expected condition (the map is a windowed cache; + * see __txn_commit_map_remove_nolock), so it is not fatal -- but a spike here + * outside of physrep rewinds / recover-to-lsn can indicate a real map-population + * bug, so it is surfaced as an observable counter. + */ +int64_t gbl_commit_map_remove_miss = 0; + typedef struct __txn_event TXN_EVENT; struct __txn_event { TXN_EVENT_T op; @@ -505,8 +514,31 @@ static int __txn_commit_map_remove_nolock(dbenv, utxnid, delete_from_logfile_lis UTXNID_TRACK * const txn = hash_find(txmap->transactions, &utxnid); if (!txn) { - logmsg(LOGMSG_ERROR, "%s: Could not find transaction %"PRIu64" in the map\n", __func__, utxnid); - ret = 1; + /* + * The commit-LSN map is a windowed, in-memory cache: it is pruned + * as log files are deleted, is rebuilt only from the last + * checkpoint forward on restart, and (on physical replicants) need + * not span a range that is being rewound / truncated. A missing + * entry is therefore an expected condition, not corruption. Report + * it as DB_NOTFOUND and let the caller decide -- recovery's backward + * pass treats it as a no-op so it can continue. + */ + ++gbl_commit_map_remove_miss; + /* + * On a large physrep rewind every committed txn in the undo window + * can miss, so rate-limit the log to at most one line per second. + * gbl_commit_map_remove_miss (see 'bdb clminfo') is the durable, + * always-on signal. Safe: this runs under txmap_mutexp. + */ + static int lastpr = 0; + const int now = comdb2_time_epoch(); + if (now != lastpr) { + logmsg(LOGMSG_WARN, "%s: transaction %"PRIu64" not in commit map " + "(nothing to remove); total misses %"PRId64"\n", + __func__, utxnid, gbl_commit_map_remove_miss); + lastpr = now; + } + ret = DB_NOTFOUND; goto err; } @@ -566,9 +598,11 @@ void __txn_commit_map_print_info(DB_ENV *dbenv, loglvl lvl, int should_lock) { if (should_lock) { Pthread_mutex_lock(&txmap->txmap_mutexp); } logmsg(lvl, "Highest logfile: %"PRId64"; " - "Smallest logfile: %"PRId64"\n", + "Smallest logfile: %"PRId64"; " + "Remove misses: %"PRId64"\n", txmap->highest_logfile, - txmap->smallest_logfile); + txmap->smallest_logfile, + gbl_commit_map_remove_miss); if (should_lock) { Pthread_mutex_unlock(&txmap->txmap_mutexp); } } diff --git a/tests/commit_lsn_map.test/runit b/tests/commit_lsn_map.test/runit index 34d8751907..ca71cfa707 100755 --- a/tests/commit_lsn_map.test/runit +++ b/tests/commit_lsn_map.test/runit @@ -261,6 +261,10 @@ extract_highest_logfile_from_clminfo() { grep -oP '(?<=Highest logfile: )[-]?[0-9]+' <<<"$1" } +extract_remove_misses_from_clminfo() { + grep -oP '(?<=Remove misses: )[-]?[0-9]+' <<<"$1" +} + verify_txmap_has_expected_min_max_files() { trap 'error $LINENO' ERR @@ -400,11 +404,99 @@ test_recover_to_lsn() { verify_correct_utxnids_in_map "$utxnids_to_recover" "$utxnids_to_be_deleted_during_recovery" "$master" } +test_recover_to_lsn_missing_map_entries() { + trap 'error $LINENO' ERR + + # Regression test: a recover-to-lsn backward pass must tolerate undoing a + # committed transaction that is absent from the commit-LSN map, rather than + # aborting the whole pass. The map is a windowed in-memory cache, so it need + # not contain every committed txn that recovery walks over (e.g. on a + # physical replicant, or across a restart / log-file prune). Before the fix, + # such a miss failed with "Could not find transaction N in the map" and the + # node could not truncate its log. + + # Given: some traffic, then an early recovery point captured after a flush. + cdb2sql ${CDB2_OPTIONS} $dbnm default 'create table tmiss(i int)' > /dev/null + cdb2sql ${CDB2_OPTIONS} $dbnm default 'insert into tmiss values(1)' > /dev/null + cdb2sql ${CDB2_OPTIONS} $dbnm default 'exec procedure sys.cmd.send("flush")' > /dev/null + + local recovery_lsn recovery_lsn_file + recovery_lsn=$(cdb2sql --tabs ${CDB2_OPTIONS} --host $master $dbnm default \ + 'exec procedure sys.cmd.send("bdb cluster")' | grep MASTER | sed 's/.*lsn //g ; s/ .*//g') + recovery_lsn_file=$(echo "$recovery_lsn" | cut -d: -f 1) + readonly recovery_lsn recovery_lsn_file + + # More committed traffic that recovery will undo, spanning higher logfiles. + insert_values 10 tmiss 1 + pushlogs $(( recovery_lsn_file + 3 )) + insert_values 10 tmiss 1 + + # Pick a logfile in the undo range that currently has map entries and drop + # just those entries from the in-memory map. The log records themselves are + # untouched, so the backward pass will still walk these committed txns -- + # but they are now missing from the map, reproducing the bug's condition. + local hole_file + hole_file=$(cdb2sql --tabs ${CDB2_OPTIONS} --host $master $dbnm \ + "select min(commitlsnfile) from comdb2_transaction_commit where commitlsnfile > $recovery_lsn_file") + readonly hole_file + if [[ -z "$hole_file" || "$hole_file" == "NULL" ]]; then + echo "FAIL: no committed txns in the undo range to remove from the map" + exit 1 + fi + + local misses_before + misses_before=$(extract_remove_misses_from_clminfo "$(get_clminfo $master)") + misses_before=${misses_before:-0} + readonly misses_before + + cdb2sql ${CDB2_OPTIONS} --host $master $dbnm \ + "exec procedure sys.cmd.send('clm_delete_logfile $hole_file')" > /dev/null + + # When: recover/truncate back to the early lsn, walking the missing entries. + cdb2sql ${CDB2_OPTIONS} --host $master $dbnm \ + "exec procedure sys.cmd.truncate_log(\"{$recovery_lsn}\")" + + # Then: the node is healthy (this query fails if the backward pass aborted + # or the node went down) ... + local alive + alive=$(cdb2sql --tabs ${CDB2_OPTIONS} --host $master $dbnm 'select 1') + if [[ "$alive" != "1" ]]; then + echo "FAIL: master unhealthy after recover-to-lsn across missing map entries" + exit 1 + fi + + # ... the pre-recovery-lsn state survived and the undone traffic is gone ... + local rowcount + rowcount=$(cdb2sql --tabs ${CDB2_OPTIONS} --host $master $dbnm 'select COUNT(*) from tmiss') + if [[ "$rowcount" != "1" ]]; then + echo "FAIL: expected 1 row in tmiss after recovery, got $rowcount" + exit 1 + fi + + # ... and we actually exercised the missing-entry path. + local misses_after + misses_after=$(extract_remove_misses_from_clminfo "$(get_clminfo $master)") + misses_after=${misses_after:-0} + readonly misses_after + if (( misses_after <= misses_before )); then + echo "FAIL: expected commit-map remove misses to increase ($misses_before -> $misses_after)" + exit 1 + fi + + # ... and the recovered table is internally consistent. + # + # Leave tmiss in place: dropping a table immediately after a recover-to-lsn + # can race with the truncate and leave residue that the suite's end-of-test + # verify trips on. test_recover_to_lsn likewise leaves its table behind. + do_verify tmiss +} + if [ "$TESTCASE" == "commit_lsn_map_delete_generated" ]; then set -o pipefail test_recover_to_lsn test_delete + test_recover_to_lsn_missing_map_entries else test_add fi