Repository navigation
fix(streams): one clock read per stream record on all four backends - #463
LeeroyHannigan wants to merge 10 commits into
Conversation
robinnsc
left a comment
robinnsc
left a comment
There was a problem hiding this comment.
Approving: nothing here blocks. The fix works. On the PostgreSQL release binaries, a PutItem that waited about 2 s on an outside row lock stored created_at 2 s before its ApproximateCreationDateTime on base and the same second on this branch, including with the server time zone set to a non-UTC offset. An upgrade from base to head on the same databases kept the sweep's selection and GetRecords ordering correct across the old and new rows. Every production writer on the four backends now takes both values from one read, and the branch merges cleanly with main and with #543. A few things:
stream_record_clockisn't in the PostgreSQL storage-level step's--testlist (integration.yml:310-313), so in CI it takes theskip()path and reports ok. It's the one test that reproduces #459 the way production hits it. The SQLite, MongoDB and Cassandra read-back tests would also pass on base, since there the two old reads were microseconds apart. So adding--test stream_record_clockthere might be worth doing in this PR.- In "Not changed here", the row in the cutoff's own second sorts before the cutoff, not after (
.sorts beforeZ), which is whycreated_at < ?deletes it. #464 has it the right way round. The edge is also a little wider than whole seconds:timetrims trailing zeros, so a cutoff with one or two fractional digits (...07.5Z) deletes up to about 99 ms early. The fix #464 proposes covers that too, so it might just be worth a note on the issue.
| // One wall-clock read feeds both the record's ApproximateCreationDateTime | ||
| // and the created_at column. The column default (NOW()) is the transaction | ||
| // start time, which in a long transaction sits seconds before the record. | ||
| let created_at = time::OffsetDateTime::now_utc(); |
There was a problem hiding this comment.
created_at now comes from the ExtendDB host's clock, while the retention sweep (stream_engine.rs:497-498) still compares it with PostgreSQL's NOW(). Before, both sides used the database clock. Now retention is offset by the skew between the app host and the database, early if the app clock is behind. Under NTP that's milliseconds and well inside the hourly sweep interval, and it's a better trade than the transaction-wait error this fixes. Still, it might be worth binding the cutoff from now_utc() as the SQLite sweep and the MongoDB defence sweep do, so each backend compares against the clock that wrote the row (prune_metrics is a precedent in this crate). With several instances each running the sweep, that moves the skew to between hosts rather than removing it, so a line in the description noting the clock source changed would also be fine.
There was a problem hiding this comment.
Agreed, and the push of 16:35 UTC (da74c30) takes the option you describe. The nextval statement now reads clock_timestamp() in the same round trip, so created_at and ApproximateCreationDateTime both come from the database clock, after the write's locking reads, and the retention sweep compares created_at with NOW() on that same clock. The host clock is no longer involved on PostgreSQL. The stream_record_clock test binds the waited record's created_at between two clock_timestamp() readings, one taken in the outside transaction before it releases the lock and one after the write returns, so a helper that reads the host clock fails it as soon as the database clock differs from the host's (it fails on main, and against a database whose clock was skewed with libfaketime in a local run). The description now says the reading is the database's clock_timestamp(), so the 24-hour window does not depend on skew between the ExtendDB host and the database, and that pre-upgrade rows carry that skew.
| // Land on the same-millisecond path, then drive the counter to the | ||
| // limit so the next call takes the overflow branch. | ||
| let (first, _) = clock.generate_with_created_at(); | ||
| clock.logical_counter = 999_999; |
There was a problem hiding this comment.
Small one: if a millisecond ticks between the two calls, the second call takes the now_ms > last_timestamp_ms branch. That also resets the counter and gives 000000 and seq > first, so every assertion passes without the overflow branch running, and nothing checks that it did. Arming it properly probably needs an injectable clock, so it may not be worth it here. Relatedly, in the test above, the normal-branch check can't tell now_ms from last_timestamp_ms because they're equal on that branch. Returning the clamped value instead survives every test, and an (before..=after).contains(&created_at_ms) assertion inside the clamp loop would catch it.
There was a problem hiding this comment.
Both points are taken in the 16:35 UTC push (0ab169e and 7caeb94). generate_with_created_at now delegates to generate_from(now_ms, reread), and the overflow tests inject both readings, so the branch runs on every run and a flag asserts that reread was called; no sleep or second wall-clock call remains in them. The clamp-branch test asserts (before..=after).contains(&created_at_ms) inside its loop, so returning the clamped prefix fails it there (the prefix sits 5 s ahead of the window). The overflow branch also changed: the prefix moves to the later of the re-read and the last prefix plus one, because under a forward clamp, or a backwards step during the wait, the re-read can sit below the last prefix, and two tests pin that case.
bbac4ed to
7ce6717
Compare
| /// sort together as text in time order. | ||
| pub(crate) fn format_epoch_millis(ms: i64) -> String { | ||
| let dt = OffsetDateTime::from_unix_timestamp_nanos(i128::from(ms) * 1_000_000) | ||
| .unwrap_or(OffsetDateTime::UNIX_EPOCH); |
There was a problem hiding this comment.
For large ms, this will default to 1970-01-01. That seems ... undesirable? Is there a more reasonable default?
There was a problem hiding this comment.
Changed in 38176a9: the SQLite formatter now stamps an out-of-range value with the current time, as the PostgreSQL engine does, so the two engines agree and such a row is not dated 1970 and swept at the next retention pass. A SystemTime reading never reaches the branch (the range ends in the year 9999), so this is the fallback for a corrupt value only. A unit test passes i64::MAX and checks for the current time in the column's shape.
| let created_at = time::OffsetDateTime::from_unix_timestamp( | ||
| record.dynamodb.approximate_creation_date_time, | ||
| ) | ||
| .unwrap_or_else(|_| time::OffsetDateTime::now_utc()); |
There was a problem hiding this comment.
This is probably similar to what the SQLite engine should be doing.
jcshepherd
left a comment
jcshepherd
left a comment
There was a problem hiding this comment.
Some inconsistencies in the default/fallback logic for timestamps between the SQLite and PostgreSQL engines.
f1708df to
7aebd15
Compare
A stream record stored two creation times from two clock reads. The record
body's ApproximateCreationDateTime was SystemTime::now() read when the record
was built. The created_at column, which the 24-hour retention sweep filters
on, was the column default: NOW() on PostgreSQL, the transaction start time,
and strftime('now') at insert time on SQLite. MongoDB read DateTime::now() a
second time in the insert. Cassandra read Utc::now() once for the HLC
sequence number and again for created_at_ms.
On PostgreSQL a write that waits inside its transaction (a row lock, a long
TransactWriteItems) stored a created_at earlier than its own
ApproximateCreationDateTime by the length of the wait, so the retention sweep
deleted it before records with the same ApproximateCreationDateTime written
in a short transaction.
Each backend now takes one wall-clock read per record and derives both
values from it. SQLite and PostgreSQL bind created_at explicitly in the
transaction path and in the write_stream_record trait method; the column
defaults stay for any other writer. SQLite writes the millisecond text shape
the default produces (24 characters), so rows from before and after this
change sort together as text. MongoDB uses one DateTime for the record and
the document. Cassandra's HybridClock gains generate_with_created_at, which
returns the sequence number and the reading it was derived from, so
created_at_ms <= hlc_ms holds for every record (the clock clamps its physical
component upward on a backwards step, never below the reading). Records
written before the upgrade keep their default-clock created_at; the
difference is at most the transaction length and ages out after 24 hours.
Tests. crates/storage-postgres/tests/stream_record_clock.rs holds a row lock
from an outside transaction while a PutItem with stream capture waits 2.1 s,
then asserts created_at's second equals ApproximateCreationDateTime on every
row, including a service-identity delete. On main the waited record stores
created_at two seconds before its own timestamp (measured: 1792765145 against
1792765147); with this change both are 1792765147. The same read-back runs on
SQLite (in-memory engine, in data/tx_helpers.rs), on Cassandra
(tests/direct/streams.rs, which also asserts created_at_ms <= hlc_ms on every
stored row), and on MongoDB (an ignored live test in backup_live_tests.rs,
run with EXTENDDB_TEST_MONGODB_URI). HybridClock unit tests pin
created_at_ms <= hlc_ms across 1,000 clamped reads and across the
counter-overflow branch, and created_at_ms equal to the wall-clock read on
the normal branch.
Closes #459.
stream_record_clock skips when EXTENDDB_TEST_PG_CONNECTION_STRING is unset, and the storage-level step that sets the variable names its test targets one by one without this test, so in CI it finished in 0.00 s on the skip path. The step now names it. The test holds a row lock from an outside transaction while a PutItem with stream capture waits 2.1 s on it, then checks that every stored created_at second equals the record's ApproximateCreationDateTime. With the created_at bind removed from the stream insert, the column falls back to NOW(), the transaction start, and the test fails on that check.
The stream helper took created_at and ApproximateCreationDateTime from
the ExtendDB host clock. The retention sweep deletes rows where
created_at < NOW() - 24 hours, on the database clock. With the host
behind the database by S seconds, every record was deleted S seconds
early, and a host more than 24 hours behind lost each record on the next
sweep.
The helper now reads clock_timestamp() in the statement that already
draws nextval('stream_seq'). Both values derive from that reading, so
each record keeps one clock read and the write adds no round trip. The
retention window is measured on the database clock again, as it was
when created_at was the column default, without the default's
transaction start offset.
The PostgreSQL clock test also reads clock_timestamp() before the outside
transaction releases the row and after the write returns. It asserts
that the waited record's created_at lies between the two reads.
When the logical counter passes 999,999, HybridClock sleeps a millisecond and re-reads the wall clock for the sequence prefix. The branch assigned the raw re-read. If the clock stepped back during the sleep, the re-read sat below the call's own reading and the returned created_at_ms exceeded the prefix of its own sequence number. Under a forward clamp the re-read sat below the previous prefix and the sequence number went backwards by the clamp width, the regression reported in issue #465; this change fixes that too. The overflow branch now sets the prefix to the later of the re-read and the previous prefix plus one. The prefix stays above every earlier reading, and the sequence number sorts after every earlier one. The doc comment states what the method returns: the wall-clock reading taken by this call, with a sequence prefix equal to that reading or a later clamped value. The clock step moved into generate_from, which takes the reading and a re-read function as arguments. A unit test drives the overflow branch with a re-read ten milliseconds below the reading and asserts created_at_ms <= hlc_ms and that the sequence follows the previous one. With the raw re-read assigned again, the test fails on the first assertion.
created_at_never_exceeds_sequence_prefix checked only created_at_ms <= hlc_ms on the clamp branch, so a clock that returned the clamped prefix in place of its reading passed. Each clamped call now has a wall-clock read on either side of it, and the test asserts that the returned value lies between the two; with the clamped prefix returned, it fails on that assertion. created_at_holds_across_counter_overflow reached the overflow branch only when its two calls fell in the same millisecond. Otherwise the second call took the first branch and every assertion still held. The test now drives the step with injected readings and asserts that the re-read ran, that created_at_ms is the call's own reading, that the prefix is the re-read, and that the counter resets. With the overflow branch skipped, it fails on the re-read assertion.
The direct streams test's comment said its service-identity delete had the TTL worker's shape. That delete goes through delete_item and stream_record_statement, while the TTL worker writes through apply_ttl_delete_effects with the TtlStreamPlan it persisted. The comment now says the delete runs through delete_item, and that the sequence prefix is the reading or a later clamped value. The TTL sweep test now reads sequence_number and created_at beside record_data on the REMOVE record and asserts created_at_ms <= hlc_ms and that ApproximateCreationDateTime is created_at_ms / 1000, the properties the direct test checks for the other writes. A plan that stores a created_at_ms one second past its reading fails the first assertion. A plan that took a second clock read microseconds after the sequence number would fail it only when a millisecond boundary fell between the two reads.
Adds the unit test #465 asks for: the last prefix 5 s ahead of the reading and the re-read a further 5 s back. The prefix moves to the last prefix plus one, the sequence follows the previous one and created_at_ms stays at or below the prefix. Flooring the overflow prefix at the reading plus one fails this test and passes the other ten. Also reword the branch comment, which compared a millisecond prefix with sequence numbers.
format_epoch_millis fell back to 1970-01-01 for a millisecond value the time crate cannot represent, so such a row would have been swept at the next retention pass. The PostgreSQL engine stamps the same case with the current time; the SQLite engine now does the same, and the two engines agree on the fallback. A SystemTime reading never reaches this branch: the range ends in the year 9999. A unit test passes i64::MAX and checks that the result is the current time in the column's shape, not 1970.
The comment said created_at is never a second clock read, while the fallback for a timestamp outside the time crate's range reads the current time. The comment now names that case and that the SQLite engine stamps it the same way.
7aebd15 to
a5f4390
Compare
Closes #459.
A stream record stored two creation times from two clock reads.
ApproximateCreationDateTimein the record body wasSystemTime::now()read when the record was built. Thecreated_atcolumn, which the 24-hour retention sweep filters on, was the column default:NOW()on PostgreSQL, the transaction start time, andstrftime('now')at insert time on SQLite. MongoDB readDateTime::now()a second time in the insert. Cassandra readUtc::now()once for the HLC sequence number and again forcreated_at_ms.On PostgreSQL a write that waits inside its transaction (a row lock, a long
TransactWriteItems) stored acreated_atearlier than its ownApproximateCreationDateTimeby the length of the wait, so the retention sweep deleted it before records with the sameApproximateCreationDateTimewritten in a short transaction. Measured onmain: aPutItemthat waited 2.1 s on a row lock storedcreated_at1792765145 againstApproximateCreationDateTime1792765147.Change
Each backend takes one wall-clock read per record and derives both values from it.
created_atexplicitly in the transaction path and in thewrite_stream_recordtrait method; the column defaults stay for any other writer. SQLite writes the millisecond text shape the default produces (24 characters), so rows from before and after this change sort together as text.On PostgreSQL the reading is the database's
clock_timestamp(), returned by the statement that already drawsnextval('stream_seq'), socreated_atstays on the clock that the retention sweep'sNOW()cutoff uses and the 24-hour window does not depend on skew between the ExtendDB host and the database.DateTimefor the record body and the document.HybridClockgainsgenerate_with_created_at, returning the sequence number and the wall-clock reading taken by the call. The sequence prefix is that reading or a later clamped value, socreated_at_ms <= hlc_ms(the 13-digit prefix of the sequence number) holds for every record. At counter overflow the prefix moves to the later of a fresh reading and the previous prefix plus one, so the prefix stays above every earlier reading and the sequence number sorts after every earlier one. That overflow change is the same line fix(cassandra): keep the HLC forward clamp across counter overflow #502 (fix/465-cassandra-hlc-overflow) carries for Cassandra HLC sequence can regress at counter overflow under a forward clamp #465; this PR needs it for the invariant above to hold on the overflow branch, so whichever of the two lands second is rebased onto the other, and Cassandra HLC sequence can regress at counter overflow under a forward clamp #465 closes through fix(cassandra): keep the HLC forward clamp across counter overflow #502. The TTL worker'sTtlStreamPlantakes both values from the same call.No schema change. Records written before the upgrade keep their default-clock
created_at. Their difference fromApproximateCreationDateTimeis at most the transaction length, plus on PostgreSQL the skew between the ExtendDB host clock and the database clock, and they age out after 24 hours.Tests
crates/storage-postgres/tests/stream_record_clock.rs: an outside transaction holds a row lock while aPutItemwith stream capture waits 2.1 s; every stored row'screated_atsecond equals itsApproximateCreationDateTime, including a service-identity delete, and the waited record'screated_atlies betweenclock_timestamp()reads taken before the lock is released and after the write returns. Fails onmainwith the values above; passes here. It now runs in the PostgreSQL storage-level step ofintegration.yml. Against a PostgreSQL whose clock ran one hour ahead of the host, it passes, and it fails on theclock_timestamp()bounds when the helper reads the host clock instead.data/tx_helpers.rsover three puts and a service-identity delete; also pins the 24-character text shape.tests/direct/streams.rsreads backsequence_number,created_atand the record, assertingcreated_at_ms <= hlc_msandcreated_at_ms / 1000 == ApproximateCreationDateTimeon every row. Runs in thedirect_integrationjob.tests/ttl_integration.rsasserts the same two properties on the TTL sweep'sREMOVErecord, which the worker writes from its persistedTtlStreamPlan; that step iscontinue-on-errorin CI (Feat/storage cassandra in tree #338).backup_live_tests.rs,#[ignore]d like its neighbours and run withEXTENDDB_TEST_MONGODB_URI(passes against a 7.0 replica set).HybridClockunit tests: across 1,000 clamped reads,created_at_msstays at or below the prefix and between wall-clock reads taken around each call. The overflow branch runs on every run from injected readings, including a re-read below the call's own reading, where the prefix stays at or above the reading and the sequence follows the previous one, and overflow under a forward clamp (the last prefix 5 s ahead of the reading, the re-read a further 5 s back), where the prefix moves to the last prefix plus one. On the normal branchcreated_at_msequals the prefix.Gates on the head:
cargo fmt,cargo +1.97.0 clippy --all-targets -- -D warnings,cargo +1.88.0 check --all-targetson the storage crates, the workspace unit tests, and the PostgreSQL and Cassandra integration tests above against PostgreSQL 16 and Cassandra 4.1.Not changed here
write_stream_recordtrait method writescreated_atat whole-second precision, which is all the record carries. It has no live caller; every data-plane write goes through the transaction helpers.