Hi Matthias,
> The title indicates constant-time recovery, but I don't see anything
> in this thread that supports this claim. Could you expand on the
> mechanisms you're using to guarantee this?
I built the v2 series and measured this, since it is checkable. Two
things, both on v2 (test_fileops is the knob: each call records one undo
record; the heap AM does not opt into UNDO, so ordinary DML generates
none).
First, a scoping note. The O(1) claim is stated for the sparse case
(README.undo:105): "a handful of filesystem or structural operations per
transaction ... O(1) from the client's perspective." It is not a claim
that total undo work is constant -- the design defers that work, it does
not remove it. So for the two client-visible costs below, the question is
really whether they stay flat as the undo chain grows past "a handful".
1) ROLLBACK latency vs undo-chain length N (one txn, N chmods, timing the
ROLLBACK only, median of 5, self-checked that the chain was actually
applied). ROLLBACK ms by undo_instant_abort_threshold regime:
- default (65536): N=200 is 0.37, N=1000 is 1.41, N=8000 is 9.74,
N=32000 is 37.6
- forced inline (large threshold): N=200 is 0.37, N=1000 is 1.81,
N=8000 is 9.43, N=32000 is 70.5
- forced deferred (threshold=1): N=200 is 0.37, N=1000 is 2.49,
N=8000 is 9.93, N=32000 is 39.1
It is linear in N in all three regimes (~1.2 us/record). Forcing the
deferred path does not make the client return in O(1): the chain is still
written and XLogFlush'd before ROLLBACK returns; deferral only moves the
physical reversal to the revert worker.
2) Crash recovery of an in-flight transaction. A backend builds N chmods
in an open txn, then the cluster is immediate-stopped. On restart the undo
phase is synchronous and the server log shows it finishing before the
cluster opens:
starting undo phase for incomplete transactions
UNDO recovery complete: 1 transactions rolled back, 128000 records applied
undo phase complete
database system is ready to accept connections (after the undo phase)
Undo phase duration, median of 2, records_applied == N every run:
N=2000 is 1.5 ms; N=32000 is 17.5 ms; N=128000 is 72.0 ms. The undo
phase is linear in N -- consistent with README.undo:119-127 (loser-txn
undo runs in the recovery pass), but it is the synchronous
undo-before-open that "constant time recovery" reads as avoiding.
None of this contradicts the mechanism -- deferring the undo of already
resolved aborts to a background worker is real and works. It is the title
and the headline O(1) that a reader takes literally. It might be worth
scoping both to the sparse case the README already assumes, or saying in
the docs that an in-flight transaction's undo is still applied at recovery
in O(chain length).
Attached are the three measurement scripts, the raw result tables, and
the recovery-log excerpt, so the numbers above can be reproduced:
ctr_rollback_latency.sh and ctr_knee.sh (test 1), ctr_recovery_time.sh
(test 2), the two .tsv outputs, and recovery_log_evidence.txt.
- Manu
#!/usr/bin/env bash
# CTR empirical test A: client-visible ROLLBACK latency vs undo-chain length N.
#
# The design (README.undo:20-25, 105-112) claims ROLLBACK returns in O(1) to
# the client for "sparse" transactions: physical undo is deferred to background
# workers above undo_instant_abort_threshold, and applied INLINE (in the
# aborting backend, before ROLLBACK returns) below it.
#
# We measure the client-visible ROLLBACK latency as N (number of undo-generating
# file ops in one transaction) grows, at three settings of the threshold
# (session-local SET; the GUC is PGC_USERSET), to separate the two regimes and
# prove the knee is caused by the threshold (calibration), not something else.
#
# Metric: wall time of the ROLLBACK statement only (psql \timing), median of R
# repeats. The N chmods hit one pre-created file; each records one undo record
# (prior mode). Nothing commits, so filesystem state is trivial and the only
# thing that scales is the undo chain length.
set -u
PORT=${PORT:-5467}
BIN=$HOME/undo-v2-inst/bin
PSQL="$BIN/psql -p $PORT -U postgres -X -q -t -A"
REPEATS=${REPEATS:-5}
NS=${NS:-"100 300 1000 3000 10000 30000 100000"}
# threshold regimes: default, forced-inline (huge), forced-deferred (tiny)
THRS=${THRS:-"65536 1000000000 1"}
OUT=${OUT:-/home/manu/Proyectos/yggdrasil/aportes/postgres-undo-ctr/logs_v2/ctr_rollback_latency.tsv}
mkdir -p "$(dirname "$OUT")"
$PSQL -c "CREATE EXTENSION IF NOT EXISTS test_fileops;" >/dev/null 2>&1
F=$($PSQL -c "SELECT test_fileops_create_tempfile('ctr_lat.dat');")
median() { sort -n | awk '{a[NR]=$1} END{ if(NR==0){print "NA"} else
if(NR%2){print a[(NR+1)/2]} else {printf "%.3f\n",(a[NR/2]+a[NR/2+1])/2} }'; }
# ROLLBACK latency (ms) for one trial at chain length N and threshold THR.
# Everything in one psql session; the LAST "Time:" line is the ROLLBACK.
one_trial() {
local n=$1 thr=$2
$PSQL 2>/dev/null <<SQL | grep -oE 'Time: [0-9.]+ ms' | tail -1 | grep -oE
'[0-9.]+'
SET undo_instant_abort_threshold = $thr;
BEGIN;
SELECT count(test_fileops_chmod('$F', (0400 + (g%2)*0200))) FROM
generate_series(1,$n) g;
\timing on
ROLLBACK;
SQL
}
echo -e "threshold\tN\trollback_ms_median\ttrials" | tee "$OUT"
for THR in $THRS; do
for n in $NS; do
vals=""
for r in $(seq 1 $REPEATS); do
t=$(one_trial "$n" "$THR")
[ -n "$t" ] && vals="${vals}${t}"$'\n'
done
med=$(printf '%s' "$vals" | median)
echo -e "$THR\t$n\t$med\t$REPEATS" | tee -a "$OUT"
done
done
echo "=== DONE ctr_rollback_latency ==="
#!/usr/bin/env bash
# Clean, reproducible knee sweep: ROLLBACK latency vs N at the DEFAULT threshold
# (65536). Fresh file per trial, fresh psql session, R repeats, median reported.
# Only the ROLLBACK is timed (\timing on sits immediately before it).
#
# Self-validating: each trial also prints the file mode AFTER rollback; it must
# equal the committed baseline, proving the undo chain was actually applied. A
# trial where it does not is reported as INVALID rather than silently trusted.
set -u
PORT=${PORT:-5467}
BIN=$HOME/undo-v2-inst/bin
PSQL="$BIN/psql -p $PORT -U postgres -X -q -t -A"
REPEATS=${REPEATS:-5}
NS=${NS:-"100 500 1000 1500 2000 2500 3000 4000 6000 10000 20000"}
THRS=${THRS:-"65536"}
$PSQL -c "CREATE EXTENSION IF NOT EXISTS test_fileops;" >/dev/null 2>&1
median() { sort -n | awk '{a[NR]=$1} END{ if(NR==0){print "NA"} else
if(NR%2){print a[(NR+1)/2]} else {printf "%.3f\n",(a[NR/2]+a[NR/2+1])/2} }'; }
# baseline mode we commit before the txn (decimal 420 = 0644, preserved by mask)
BASE=420
echo -e "threshold\tN\trollback_ms_median\ttrials\tvalid"
for thr in $THRS; do
for n in $NS; do
vals=""; bad=0
for r in $(seq 1 $REPEATS); do
out=$($PSQL 2>/dev/null <<SQL
SELECT test_fileops_create_tempfile('knee_${thr}_${n}_${r}.dat') AS f \gset
SELECT test_fileops_chmod(:'f', $BASE);
SET undo_instant_abort_threshold = $thr;
BEGIN;
SELECT count(test_fileops_chmod(:'f',(500+(g%2)*20))) FROM
generate_series(1,$n) g;
\timing on
ROLLBACK;
\timing off
SELECT 'MODE=' || test_fileops_get_mode(:'f');
SQL
)
t=$(printf '%s' "$out" | grep -oE 'Time: [0-9.]+ ms' | tail -1 | grep -oE
'[0-9.]+')
m=$(printf '%s' "$out" | grep -oE 'MODE=[0-9]+' | cut -d= -f2)
if [ "$m" != "$BASE" ]; then bad=$((bad+1)); fi
[ -n "$t" ] && vals="${vals}${t}"$'\n'
done
med=$(printf '%s' "$vals" | median)
valid=$([ "$bad" -eq 0 ] && echo yes || echo "NO($bad/$REPEATS)")
echo -e "$thr\t$n\t$med\t$REPEATS\t$valid"
done
done
echo "=== DONE knee ==="
#!/usr/bin/env bash
# CTR empirical test B: crash-recovery UNDO-PHASE duration vs in-flight chain.
#
# README.undo:119-127 says a transaction that wrote UNDO but was caught
# in-flight by a crash (neither COMMIT nor ABORT) has its UNDO chain "walked
# and applied during this recovery pass". This build logs that pass explicitly:
#
# LOG: starting undo phase for incomplete transactions
# LOG: UNDO recovery complete: 1 transactions rolled back, <N> records applied
# LOG: undo phase complete
# LOG: database system is ready to accept connections (AFTER the undo phase)
#
# So the undo phase runs synchronously before the cluster opens. We measure its
# duration (from the server log's millisecond timestamps) as a function of the
# in-flight chain length N, and confirm "records applied" == N (the chain
# survived the crash and was fully applied).
#
# Protocol per N: fresh start; a background psql builds an in-flight txn of N
# chmods, touches a readiness file, holds the txn open (pg_sleep); the driver
# waits for the file, then immediate-stops (crash); restart; parse the undo
# phase from the log.
set -u
PORT=${PORT:-5467}
BIN=$HOME/undo-v2-inst/bin
DATA=$HOME/undo-v2-data
SRVLOG=$DATA/server.log
PSQL="$BIN/psql -p $PORT -U postgres -X -q -t -A"
REPEATS=${REPEATS:-2}
NS=${NS:-"2000 8000 32000 128000"}
SIG=/tmp/ctr_ready
LOGDIR=/home/manu/Proyectos/yggdrasil/aportes/postgres-undo-ctr/logs_v2
mkdir -p "$LOGDIR"
OUT=${OUT:-$LOGDIR/ctr_recovery_time.tsv}
ensure_up() { $BIN/pg_ctl -D "$DATA" -l "$SRVLOG" -w start >/dev/null 2>&1; }
median() { sort -n | awk '{a[NR]=$1} END{ if(NR==0){print "NA"} else
if(NR%2){print a[(NR+1)/2]} else {printf "%.3f\n",(a[NR/2]+a[NR/2+1])/2} }'; }
# ms between two "HH:MM:SS.mmm" server-log stamps on the given grep patterns,
# taken from the TAIL of the log (this restart).
phase_ms() {
awk '
/starting undo phase/ {t0=stamp($0)}
/database system is ready/ {t1=stamp($0); print (t1-t0)*1000; exit}
function stamp(l, a,hh,mm,ss){ split(l,a," "); split(a[2],h,":"); return
h[1]*3600+h[2]*60+h[3] }
' "$SRVLOG" 2>/dev/null | tail -1
}
ensure_up
$PSQL -c "CREATE EXTENSION IF NOT EXISTS test_fileops;" >/dev/null 2>&1
F=$($PSQL -c "SELECT test_fileops_create_tempfile('ctr_rec.dat');")
# one trial: returns "undo_ms<TAB>records_applied<TAB>ready_after_undo(0/1)"
one_trial() {
local n=$1
ensure_up
rm -f "$SIG"
( $BIN/psql -p "$PORT" -U postgres -X -q -t -A >/dev/null 2>&1 <<SQL
BEGIN;
SELECT count(test_fileops_chmod('$F', (0400 + (g%2)*0200))) FROM
generate_series(1,$n) g;
\! touch $SIG
SELECT pg_sleep(120);
SQL
) &
local waited=0
while [ ! -f "$SIG" ]; do sleep 0.3; waited=$((waited+1)); [ $waited -gt 1200
] && { echo "NA\tNA\tNA"; return; }; done
sleep 0.3
# mark the log so phase_ms only sees this restart
local mark_lines
mark_lines=$(wc -l < "$SRVLOG")
$BIN/pg_ctl -D "$DATA" -m immediate -w stop >/dev/null 2>&1
$BIN/pg_ctl -D "$DATA" -l "$SRVLOG" -w start >/dev/null 2>&1
# parse only lines from this restart onward
local seg; seg=$(tail -n +"$mark_lines" "$SRVLOG")
local ums rec order
ums=$(printf '%s\n' "$seg" | awk '
/starting undo phase/ {split($2,h,":"); t0=h[1]*3600+h[2]*60+h[3]}
/undo phase complete/ {split($2,h,":"); t1=h[1]*3600+h[2]*60+h[3];
print (t1-t0)*1000; exit}')
rec=$(printf '%s\n' "$seg" | grep -oE '[0-9]+ records applied' | grep -oE
'^[0-9]+' | tail -1)
# ordering check: does "undo phase complete" appear BEFORE "ready to accept"?
local lc_undo lc_ready
lc_undo=$(printf '%s\n' "$seg" | grep -n "undo phase complete" | head -1 |
cut -d: -f1)
lc_ready=$(printf '%s\n' "$seg" | grep -n "ready to accept" | head -1 | cut
-d: -f1)
if [ -n "$lc_undo" ] && [ -n "$lc_ready" ] && [ "$lc_undo" -lt "$lc_ready" ];
then order=1; else order=0; fi
printf '%s\t%s\t%s\n' "${ums:-NA}" "${rec:-NA}" "$order"
}
echo -e
"N_inflight\tundo_phase_ms_median\trecords_applied\tundo_before_open\ttrials" |
tee "$OUT"
for n in $NS; do
mss=""; rec=""; ord=""
for r in $(seq 1 $REPEATS); do
res=$(one_trial "$n")
m=$(printf '%s' "$res" | cut -f1); a=$(printf '%s' "$res" | cut -f2);
o=$(printf '%s' "$res" | cut -f3)
[ "$m" != "NA" ] && mss="${mss}${m}"$'\n'
rec="$a"; ord="$o"
done
med=$(printf '%s' "$mss" | median)
echo -e "$n\t$med\t$rec\t$ord\t$REPEATS" | tee -a "$OUT"
done
echo "=== DONE ctr_recovery_time ==="
[integrity] limpio carril a: calib=48342us (idle=48342us, +0%)
threshold N rollback_ms_median trials valid
65536 200 0.368 5 yes
65536 500 0.742 5 yes
65536 1000 1.408 5 yes
65536 2000 2.590 5 yes
65536 4000 4.890 5 yes
65536 8000 9.742 5 yes
65536 16000 18.969 5 yes
65536 32000 37.561 5 yes
1000000000 200 0.368 5 yes
1000000000 500 0.831 5 yes
1000000000 1000 1.808 5 yes
1000000000 2000 2.671 5 yes
1000000000 4000 4.911 5 yes
1000000000 8000 9.431 5 yes
1000000000 16000 28.931 5 yes
1000000000 32000 70.456 5 yes
1 200 0.370 5 yes
1 500 0.962 5 yes
1 1000 2.488 5 yes
1 2000 2.808 5 yes
1 4000 4.969 5 yes
1 8000 9.926 5 yes
1 16000 42.535 5 yes
1 32000 39.124 5 yes
=== DONE knee ===
N_inflight undo_phase_ms_median records_applied undo_before_open
trials
2000 1.500 2000 1 2
8000 4.500 8000 1 2
32000 17.500 32000 1 2
128000 72.000 128000 1 2
2026-10-05 15:23:49.421 -03 [341340] LOG: starting undo phase for incomplete
transactions
2026-10-05 15:23:49.421 -03 [341340] LOG: UNDO recovery: 1 incomplete
transaction(s) to roll back
2026-10-05 15:23:49.493 -03 [341340] LOG: UNDO recovery complete: 1
transactions rolled back, 128000 records applied
2026-10-05 15:23:49.493 -03 [341340] LOG: undo phase complete
2026-10-05 15:23:49.513 -03 [341333] LOG: database system is ready to accept
connections
2026-10-05 15:25:46.432 -03 [343898] LOG: redo starts at 0/1C0DB5B8
2026-10-05 15:25:46.502 -03 [343898] LOG: redo done at 0/1DA52868 system
usage: CPU: user: 0.01 s, system: 0.05 s, elapsed: 0.06 s
2026-10-05 15:25:46.502 -03 [343898] LOG: starting undo phase for incomplete
transactions
2026-10-05 15:25:46.502 -03 [343898] LOG: UNDO recovery: 1 incomplete
transaction(s) to roll back
2026-10-05 15:25:46.574 -03 [343898] LOG: UNDO recovery complete: 1
transactions rolled back, 128000 records applied
2026-10-05 15:25:46.574 -03 [343898] LOG: undo phase complete
2026-10-05 15:25:46.592 -03 [343891] LOG: database system is ready to accept
connections
