Measure an actual RTO end to end, stage by stage

Objective

Most recovery-time figures are one number with no derivation. This lab replaces that number with ten, by timing each stage of a real recovery separately and writing the results to a file.

You will destroy a running service, recover it from an offsite repository onto a tree that has never existed, and validate the result twice. The finding is not the total but which stage dominates it, because that is where engineering effort changes the answer.

Architecture

Ten stages in sequence. The dotted edge is the claim this lab refutes.

flowchart LR
    LOSS["data loss at t0"] --> DET["detection<br/>bounded by the<br/>health-check interval"]
    DET --> DEC["decision<br/>human interval,<br/>recorded by no tool"]
    DEC --> PROV["provisioning<br/>clean target tree"]
    PROV --> RETR["retrieval<br/>list snapshots,<br/>pick the recovery point"]
    RETR --> XFER["transfer<br/>offsite repo to<br/>local staging"]
    XFER --> DECR["decryption<br/>escrow key plus first<br/>authenticated read"]
    DECR --> REST["restore<br/>writes every byte,<br/>never incremental"]
    REST --> DEP["dependency startup<br/>service answers on 18080"]
    DEP --> DVAL["data validation<br/>md5sum -c manifest"]
    DVAL --> BVAL["business validation<br/>order total matches"]
    BVAL --> RTO["measured RTO<br/>sum of all ten stages"]
    BKP["nightly backup duration<br/>incremental, small, green"] -.->|predicts none of this| RTO

Requirements

• A disposable host or nested VM with about 1 GB free under $HOME. Everything this lab creates lives under one directory and carries the rbdr- prefix so cleanup can be scoped and asserted.
• restic, GNU tar, rsync, curl, python3, awk and md5sum. The transcripts quoted below were captured on restic 0.19.1 and restic 0.18.0; your versions will differ and your seconds certainly will.
• date +%s.%N, from GNU coreutils. The harness needs sub-second resolution: several stages finish in under a second here and take minutes on real storage.
• TCP 18080 free on loopback. Task 1 checks it.

Scenario

An order service has a documented four-hour RTO. The figure came from a spreadsheet: the nightly job takes eleven minutes, so a restore was assumed to take about the same plus a margin. Nobody has run one.

You have been asked to replace that assumption with a measurement.

Tasks

Task 1 — Record pre-lab state

LAB="$HOME/rbdr-lab-25"
SRC="$LAB/rbdr-prod"
OFFSITE="$LAB/rbdr-offsite"
STAGE_DIR="$LAB/rbdr-staging"
TARGET="$LAB/rbdr-recovered"
mkdir -p "$LAB"

{
  date -Is
  restic version
  tar --version | head -1
  echo "--- rbdr paths already in HOME ---"
  find "$HOME" -maxdepth 1 -name 'rbdr-*' ! -name 'rbdr-lab-25' -print | sort
  echo "--- listeners on 18080 ---"
  ss -lnt 2>/dev/null | grep ':18080' || echo none
} | tee "$LAB/state.pre-lab"

The two inventories must be empty. Cleanup runs the same block and diffs against this file, so a stray rbdr- path here becomes a false failure later — and invites you to delete somebody else’s data on the strength of a prefix collision.

Task 2 — Build the service and its recovery point

mkdir -p "$SRC/app" "$SRC/db" "$OFFSITE" "$STAGE_DIR"
printf 'ORDER-1001,4500.00\nORDER-1002,1250.00\nORDER-1003,880.00\n' > "$SRC/app/orders.csv"
printf 'config v2\n' > "$SRC/app/app.conf"
head -c 33554432 /dev/urandom > "$SRC/db/data.bin"

( cd "$SRC" && find . -type f -exec md5sum {} + | sort -k2 ) > "$LAB/manifest.md5"
awk -F, '{ t += $2 } END { printf "%.2f\n", t }' "$SRC/app/orders.csv" > "$LAB/expected-total.txt"
cat "$LAB/expected-total.txt"

Two properties are recorded at backup time: a checksum manifest and a business figure. A restore inspected for plausibility instead of compared against a recorded property is not validated, it is glanced at.

printf 'rbdr-lab-25-passphrase\n' > "$LAB/rbdr-escrow.key"
chmod 600 "$LAB/rbdr-escrow.key"
export RESTIC_REPOSITORY="$OFFSITE/repo"
export RESTIC_PASSWORD_FILE="$LAB/rbdr-escrow.key"

restic init
restic backup --tag daily "$SRC"
LAST_BACKUP_AT=$(date +%s)

sleep 5
printf 'ORDER-1004,300.00\n' >> "$SRC/app/orders.csv"
LOST_WRITE_AT=$(date +%s)
echo "RPO window so far: $(( LOST_WRITE_AT - LAST_BACKUP_AT ))s"

ORDER-1004 is written after the recovery point. It is therefore not in the repository, and the recovery will not produce it. That gap is the observed RPO, and it is a property of when the backup ran, never of restic.

$ restic snapshots

ID        Time                 Host          Tags        Paths       Size
-------------------------------------------------------------------------------
3fe43af4  2026-08-28 13:27:02  8211a08b55c3  daily       /work/prod  60.000 MiB
3e349a12  2026-08-28 13:27:03  8211a08b55c3  daily       /work/prod  60.000 MiB
-------------------------------------------------------------------------------
Timestamps shown in local time
2 snapshots

Task 3 — Start the service and the health check

python3 -m http.server 18080 --directory "$SRC/app" > "$LAB/service.log" 2>&1 &
SVC_PID=$!
sleep 2
curl -fsS "http://127.0.0.1:18080/orders.csv" | tail -1

The service is a stand-in; the health check is the real thing, an external observer that either gets the file or does not. Detection is measured against it, not against a log line.

Task 4 — Install the stage harness

STAGES="$LAB/stages.tsv"
: > "$STAGES"
: > "$LAB/run.log"

stage() {
  n=$1; shift
  t0=$(date +%s.%N)
  "$@" >> "$LAB/run.log" 2>&1
  rc=$?
  t1=$(date +%s.%N)
  awk -v n="$n" -v a="$t0" -v b="$t1" -v r="$rc" \
    'BEGIN { printf "%s\t%.2f\t%d\n", n, b - a, r }' >> "$STAGES"
  return "$rc"
}

record() {
  awk -v n="$1" -v s="$2" 'BEGIN { printf "%s\t%.2f\t0\n", n, s }' >> "$STAGES"
}

stage times a command and keeps its exit code, because a stage that finished fast by failing is not a fast stage. record covers the stages no command performs.

Task 5 — Lose the service, and time detection and decision

POLL=10
( while curl -fsS -o /dev/null "http://127.0.0.1:18080/orders.csv"; do sleep "$POLL"; done
  date +%s.%N > "$LAB/detected-at" ) &
DETECTOR=$!

sleep 3
kill "$SVC_PID" 2>/dev/null
rm -rf "$SRC"
LOSS_AT=$(date +%s.%N)

wait "$DETECTOR"
record detection "$(awk -v a="$LOSS_AT" -v b="$(cat "$LAB/detected-at")" 'BEGIN { print b - a }')"

DECISION_START=$(date +%s)
echo "Read the runbook. Confirm the recovery point. Get authorisation. Then continue."
record decision "$(( $(date +%s) - DECISION_START ))"

Detection is bounded by POLL, and no change to the backup system moves it. Decision is a human interval that appears in no dashboard; recording it as zero is the commonest way a stage table lies.

Task 6 — Provision, retrieve, transfer, decrypt, restore

provision() { mkdir -p "$TARGET" "$STAGE_DIR" && test ! -e "$TARGET/app"; }
stage provisioning provision

export RESTIC_REPOSITORY="$OFFSITE/repo"
stage retrieval restic snapshots --tag daily

stage transfer rsync -a "$OFFSITE/repo/" "$STAGE_DIR/repo/"

export RESTIC_REPOSITORY="$STAGE_DIR/repo"
stage decryption restic cat config

stage restore restic restore latest --target "$TARGET"
RESTORED="$TARGET$SRC"
ls "$RESTORED/app"

restic recreates the snapshot’s absolute paths beneath --target, so the recovered tree sits at $TARGET plus the original path; that concatenation is what RESTORED holds, and the ls above confirms it before any later stage depends on it. The decryption stage here is a floor, not a measurement: the key was already on disk. In production this stage also includes fetching it from escrow, a process with an on-call rota attached.

$ restic restore 3fe43af4 --target /work/restore, then md5sum -c against the 09:00 manifest

restoring snapshot 3fe43af4 of [/work/prod] at 2026-08-28 13:27:02.65376235 +0000 UTC by root@8211a08b55c3 to /work/restore
Summary: Restored 7 files/dirs (60.000 MiB) in 0:00
>>> exit code: 0

--- comparing the restored tree against the 09:00 checksums ---
./app/app.conf: OK
./app/orders.csv: OK
./db/data.bin: OK
>>> md5sum -c exit code: 0

Task 7 — Start dependencies, then validate twice

depstart() {
  python3 -m http.server 18080 --directory "$RESTORED/app" > "$LAB/service.log" 2>&1 &
  echo $! > "$LAB/rbdr-svc.pid"
  until curl -fsS -o /dev/null "http://127.0.0.1:18080/orders.csv"; do sleep 1; done
}
stage dependency_startup depstart

validate_data() { cd "$RESTORED" && md5sum -c "$LAB/manifest.md5"; }
stage data_validation validate_data

validate_business() {
  got=$(awk -F, '{ t += $2 } END { printf "%.2f\n", t }' "$RESTORED/app/orders.csv")
  want=$(cat "$LAB/expected-total.txt")
  echo "restored total $got, recorded total $want"
  test "$got" = "$want"
}
stage business_validation validate_business

Data validation says the bytes match what was stored. Business validation says the service computes the figure the business recorded. They fail independently, and passing only the first is a recovery nobody has agreed to trust.

Task 8 — Produce the stage table

awk -F'\t' 'BEGIN { printf "%-22s %9s %4s\n", "STAGE", "SECONDS", "RC" }
            { printf "%-22s %9.2f %4d\n", $1, $2, $3 }' "$STAGES" | tee "$LAB/stage-table.txt"

awk -F'\t' '{ s += $2; if ($2 > m) { m = $2; w = $1 } }
            END { printf "total %.2fs; dominant stage %s at %.2fs, %.0f%% of the total\n",
                         s, w, m, 100 * m / s }' "$STAGES" | tee "$LAB/rto-report.txt"

$ awk over stages.tsv, printing stage, seconds and exit code

STAGE                    SECONDS   RC
detection                   ....    0
decision                    ....    0
provisioning                ....    0
retrieval                   ....    0
transfer                    ....    0
decryption                  ....    0
restore                     ....    0
dependency_startup          ....    0
data_validation             ....    0
business_validation         ....    0

Task 9 — Why the nightly duration predicted none of it

The nightly job is incremental: it stores what changed. A restore is not. It writes every byte of the recovery point, every time.

$ the harness summarising backup and restore seconds for two datasets of the same size

                                   backup    restore
400 MiB in 1 file                 1.49s      1.07s
400 MiB in 8000 files             1.29s      1.36s

Read that honestly. The file-count effect here is modest: 8000 small files took about a fifth longer to restore than the same bytes in one file. The capture ran on tmpfs, which removes seek time, queue depth and network, so it isolates per-file overhead inside the tool and nothing else. Those seconds belong to that machine on that date.

$ a second backup of the unchanged dataset, beside the first backup and the restore

--- the asymmetry that IS large, and is the point of the exercise ---
a second backup of 'big' with nothing changed:
backup  : .73s

first backup of 400 MiB : 1.49s
second backup, unchanged: .73s
restore of 400 MiB      : 1.07s

Task 10 — The failing case: a chain with a missing member

CHAIN="$LAB/rbdr-chain"
mkdir -p "$CHAIN/src" "$CHAIN/arch" "$CHAIN/broken"
printf 'ORDER-1001,4500.00\n' > "$CHAIN/src/orders.csv"
printf 'config v1\n' > "$CHAIN/src/app.conf"
cd "$CHAIN"
tar --listed-incremental=snap.db -cf arch/L0.tar src
printf 'ORDER-1002,1250.00\n' >> src/orders.csv
tar --listed-incremental=snap.db -cf arch/L1.tar src
printf 'config v2\n' > src/app.conf
tar --listed-incremental=snap.db -cf arch/L2.tar src

cd "$CHAIN/broken"
tar --incremental -xf ../arch/L0.tar
tar --incremental -xf ../arch/L2.tar
echo ">>> exit code: $?"
{ cat src/orders.csv; cat src/app.conf; } | tee "$LAB/chain-report.txt"

$ replay L0 then L2 with L1 absent, then read the two files back

--- correct restore: replay L0, then L1, then L2 ---
orders.csv:
  ORDER-1001,4500.00
  ORDER-1002,1250.00
app.conf  : config v2

--- now L1 is unreadable: retention removed it, or its media failed ---
after L0 only:
  orders.csv: ORDER-1001,4500.00 
  app.conf  : config v1
skipping L1 (missing) and applying L2:
  orders.csv: ORDER-1001,4500.00 
  app.conf  : config v2

The replay reported nothing. app.conf is at its newest version, so the tree looks current, while orders.csv is missing a line forever. Chain length is a risk for exactly this reason, and only a property recorded at backup time distinguishes a complete tree from a plausible one.

Validation

wc -l < "$STAGES"

awk -F'\t' '$3 != 0 { print "FAILED STAGE: " $1; bad = 1 } END { exit bad }' "$STAGES"
echo "rc-scan exit: $?"

( cd "$RESTORED" && md5sum -c "$LAB/manifest.md5" ) > "$LAB/verify.out" 2>&1
echo "md5sum -c exit: $?"
tail -1 "$LAB/verify.out"

grep -c 'ORDER-1004' "$RESTORED/app/orders.csv"; echo "grep-1004 exit: $?"
grep -c 'ORDER-1002' "$LAB/chain-report.txt"; echo "grep-1002 exit: $?"

grep -q 'dominant stage' "$LAB/rto-report.txt"; echo "report exit: $?"
cat "$LAB/rto-report.txt"

Neither the awk scan nor the checksum comparison is piped, on purpose: a pipe returns the exit code of its last stage, so md5sum -c | tail -1 reports success even when a file failed.

The two checks that exit 1 are the load-bearing ones. ORDER-1004 must be absent, because it was written after the recovery point; ORDER-1002 must be absent from the broken chain, because L1 was never applied. A 0 count with exit 1 is the pass condition here, and a check treating any non-zero exit as an error reports both backwards.

Expected Outcome

stage-table.txt holds ten lines, each with measured seconds and exit code 0. rto-report.txt names one dominant stage and its share of the total. With POLL at ten seconds and 32 MiB on local disk, the dominant stage here is normally detection or decision rather than restore — which is the point, because those are the two stages no backup product shortens for you.

Record all three numbers from your own run:

• Actual restore time: _______ seconds, the restore row of stages.tsv alone.
• Actual measured RTO: _______ seconds, the total from rto-report.txt, and the dominant stage was _______ at _____%.
• Actual RPO observed: _______ seconds, the interval between LAST_BACKUP_AT and LOST_WRITE_AT in Task 2. ORDER-1004 fell in that window and did not come back.

Troubleshooting

Fatal: unable to open config file in the retrieval stage. RESTIC_REPOSITORY points at the staging copy from a previous attempt. Re-export it before each stage that uses it; the harness does not manage environment for you.

Fatal: wrong password or no key found, exit 12. The escrow file was removed, or RESTIC_PASSWORD_FILE is unset. Recreate it exactly as in Task 2; a trailing newline difference changes the passphrase.

ls: cannot access ...: No such file or directory after restore. RESTORED was computed before SRC was set, or SRC was relative. find "$TARGET" -name orders.csv locates the real path.

The detection stage never returns. The old server was not killed, so the health check still succeeds. kill "$SVC_PID" first, then confirm with ss -lnt | grep 18080.

Address already in use during dependency startup. The Task 3 server is still bound to 18080. Kill the PID in rbdr-svc.pid.

md5sum: manifest.md5: No such file or directory. validate_data ran without cd succeeding, because RESTORED does not exist — a restore failure surfacing one stage late.

The chain replay prints Cannot open: No such file or directory. Wrong working directory: ../arch/L0.tar assumes $CHAIN/broken.

Cleanup prints sed: can't read .../state.pre-lab. Task 1 was skipped, or $LAB differs between the two shells. Cleanup then has no baseline and cannot prove anything; re-run Task 1’s block before deleting, or record that this run’s cleanup is unverified.

Cleanup

kill "$(cat "$LAB/rbdr-svc.pid" 2>/dev/null)" 2>/dev/null

BASELINE="/tmp/rbdr-lab-25-state.pre-lab"
POST="/tmp/rbdr-lab-25-state.post-lab"
sed -n '/--- rbdr paths/,$p' "$LAB/state.pre-lab" > "$BASELINE"

cd "$HOME"
rm -rf "$LAB"

{
  echo "--- rbdr paths already in HOME ---"
  find "$HOME" -maxdepth 1 -name 'rbdr-*' ! -name 'rbdr-lab-25' -print | sort
  echo "--- listeners on 18080 ---"
  ss -lnt 2>/dev/null | grep ':18080' || echo none
} > "$POST"

diff "$BASELINE" "$POST" \
  && echo "CLEAN: post-lab inventory matches the Task 1 baseline"
rm -f "$BASELINE" "$POST"

The baseline is copied out before $LAB is deleted, so the comparison is against the inventories Task 1 recorded, not against expected text written here. diff exiting 0 with CLEAN printed is the assertion; anything else names what survived.

Production notes

• Publish the stage table, not the total. A four-hour RTO with no derivation cannot be improved, because nobody knows which hour to attack.
• Detection is bounded by your check interval, decision by your escalation path. Both are usually cheaper to shorten than restore throughput, and neither appears on any vendor datasheet.
• Time decryption with the key actually in escrow. A key fetch needing two approvers at 03:00 is a stage, often the longest one.
• Never restore over production before the recovery has been validated in isolation; that destroys the fallback and the evidence together.
• Re-measure after any change to dataset size, storage class or offsite location. A number measured once has an expiry date.

What You Learned

• A recovery is ten stages, and only one of them is the restore. Timing them separately turns an assumption into a table you can act on.
• Backup duration does not predict restore duration. The captured contrast is explicit: a first backup of 400 MiB took 1.49s, an unchanged second backup 0.73s, and the restore 1.07s, because backup work is incremental and restore work is not.
• The file-count effect in that capture was modest — about a fifth — because tmpfs removed seek, queue and network, leaving only per-file overhead inside the tool.
• An incremental chain missing one member replays silently. With L1 gone, app.conf came back at its newest version and orders.csv came back one line short, with no error reported.
• Two validations, not one. Bytes matching a recorded manifest and a business figure matching a recorded total fail independently, and passing only the first is not a recovery anyone has agreed to accept.