Skip to content

Commit aff3e16

Browse files
committed
compute: add a lifecycle event log for compute exports
Record each compute export's lifecycle as an append-only log, `mz_introspection.mz_compute_lifecycle_events_per_worker`, rather than as more timestamp columns on the hydration time relation. Two things stop timestamp columns from carrying the lifecycle. The stages do not share a grain: `installed`, `started` and `hydrated` are per-worker facts, since each worker hydrates its own fragment of the dataflow, while whether the output is durable is a property of the sink as a whole, maintained on one elected worker. And a timestamp cannot say why the next stage has not happened, so a NULL cannot tell a replacement materialized view waiting for a cutover apart from an index that will never write. export_id text not null worker_id uint8 not null event text not null occurred_at timestamptz not null reason text nullable details jsonb nullable `installed`, `started` and `hydrated` are logged by every worker. The write stages are logged only by the worker that maintains the sink's shared write frontier, so they appear once per object and the row records which worker was elected. An index emits the first three and stops, which is the index degeneracy of the lifecycle falling out of the model rather than being special-cased. `hydrated` reads the dataflow's own progress frontier, the compute probe, not the reported output frontier. The output frontier folds in the write frontier, which makes it a measure of durability, and for a sink-backed collection it is not even uniform across workers: `mint` clears the shared frontier on every non-elected worker, where it is the empty antichain and contributes nothing to the meet. `mz_compute_hydration_times_per_worker` is unchanged, so `hydrated_at` and `time_ns` keep reporting exactly what they reported before, and the new relation carries the dataflow reading alongside. The write stages are gated on hydration. Before it the sink has produced nothing and read-only mode is holding nothing back, and every collection starts read-only, so reporting a block from installation would put a `write_blocked` and a `write_unblocked` on essentially every materialized view, both ahead of `hydrated`. Gating also keeps `written` ordered after `hydrated`, which it is not otherwise: `apply_refresh` rounds a `REFRESH` materialized view's frontier up to the next refresh time off its input frontier, before the dataflow computes anything, so the sink writes an empty batch for the pre-refresh window and the shard's upper passes the as-of while the dataflow is still hydrating. That also means a refresh schedule advances writing rather than blocking it, so there is no `refresh` cause for `write_blocked` to report. `details` carries the dataflow's as-of, which every stage is defined relative to: without it the interval between two stages says nothing about how much work was done, since a replacement materialized view with a far behind as-of is a completely different amount of work at the same duration. Part of CPU-226 Co-Authored-By: Claude <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_018ZVCMBSLdxzGus78ZKWhZz
1 parent f9be4ed commit aff3e16

23 files changed

Lines changed: 904 additions & 40 deletions

File tree

doc/developer/design/20260817_compute_hydration_timestamps.md

Lines changed: 233 additions & 28 deletions
Large diffs are not rendered by default.

doc/user/content/reference/system-catalog/mz_introspection.md

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -464,6 +464,7 @@ The `mz_scheduling_parks_histogram` view describes a histogram of [dataflow] wor
464464
[query hints]: /sql/select/#query-hints
465465

466466
<!-- RELATION_SPEC_UNDOCUMENTED mz_introspection.mz_compute_hydration_times_per_worker -->
467+
<!-- RELATION_SPEC_UNDOCUMENTED mz_introspection.mz_compute_lifecycle_events_per_worker -->
467468
<!-- RELATION_SPEC_UNDOCUMENTED mz_introspection.mz_compute_operator_hydration_statuses_per_worker -->
468469
<!-- RELATION_SPEC_UNDOCUMENTED mz_introspection.mz_dataflow_operator_reachability -->
469470
<!-- RELATION_SPEC_UNDOCUMENTED mz_introspection.mz_dataflow_operator_reachability_per_worker -->

src/adapter/src/catalog/open/builtin_schema_migration.rs

Lines changed: 22 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -416,6 +416,28 @@ static MIGRATIONS: LazyLock<Vec<MigrationStep>> = LazyLock::new(|| {
416416
MZ_CATALOG_SCHEMA,
417417
"mz_views",
418418
),
419+
// Required because we added the `mz_compute_lifecycle_events_per_worker` builtin log.
420+
// make_mz_indexes inlines one VALUES row per builtin log, naming the log and its
421+
// `index_by` columns, so adding or removing a log changes the SQL fingerprint of
422+
// `mz_indexes` just as adding a builtin index does. See the NOTE above: this version
423+
// must stay at the workspace's current dev version until the change ships.
424+
MigrationStep::replacement(
425+
"26.40.0-dev.0",
426+
CatalogItemType::MaterializedView,
427+
MZ_CATALOG_SCHEMA,
428+
"mz_indexes",
429+
),
430+
// Adding a builtin log moves two generated materialized views, not one:
431+
// make_mz_sources inlines a VALUES row per builtin log alongside the builtin sources,
432+
// so `mz_sources` needs the same treatment. Without it, an upgrade from a released
433+
// version reaches `update_fingerprints` with a mismatch for a builtin that is neither
434+
// migrated nor ephemeral, which panics and blocks catalog open.
435+
MigrationStep::replacement(
436+
"26.40.0-dev.0",
437+
CatalogItemType::MaterializedView,
438+
MZ_CATALOG_SCHEMA,
439+
"mz_sources",
440+
),
419441
]
420442
});
421443

src/catalog/src/builtin.rs

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1106,6 +1106,7 @@ pub static BUILTINS_STATIC: LazyLock<Vec<Builtin<NameReference>>> = LazyLock::ne
11061106
Builtin::Log(&MZ_COMPUTE_IMPORT_FRONTIERS_PER_WORKER),
11071107
Builtin::Log(&MZ_COMPUTE_ERROR_COUNTS_RAW),
11081108
Builtin::Log(&MZ_COMPUTE_HYDRATION_TIMES_PER_WORKER),
1109+
Builtin::Log(&MZ_COMPUTE_LIFECYCLE_EVENTS_PER_WORKER),
11091110
Builtin::Log(&MZ_COMPUTE_OPERATOR_HYDRATION_STATUSES_PER_WORKER),
11101111
Builtin::MaterializedView(&MZ_KAFKA_SINKS),
11111112
Builtin::MaterializedView(&MZ_KAFKA_CONNECTIONS),
@@ -2220,6 +2221,21 @@ mod tests {
22202221
Fingerprint::fingerprint(&&mv_extra),
22212222
"mz_sources fingerprint must change when a builtin source is added"
22222223
);
2224+
2225+
// Adding an extra log must also change the fingerprint, because the log set is inlined
2226+
// alongside the source set. Without this case, adding a builtin log moves the
2227+
// `mz_sources` fingerprint with nothing on the PR path to announce that it needs a
2228+
// migration step, and catalog open panics on the upgrade.
2229+
let extra_log = logs[0];
2230+
let mv_extra_log = builtin::make_mz_sources(
2231+
sources.iter().copied(),
2232+
logs.iter().copied().chain(std::iter::once(extra_log)),
2233+
);
2234+
assert_ne!(
2235+
fp_base,
2236+
Fingerprint::fingerprint(&&mv_extra_log),
2237+
"mz_sources fingerprint must change when a builtin log is added"
2238+
);
22232239
}
22242240

22252241
/// Verifies that the `mz_indexes` materialized view fingerprint changes

src/catalog/src/builtin/mz_introspection.rs

Lines changed: 35 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -342,6 +342,41 @@ pub static MZ_COMPUTE_HYDRATION_TIMES_PER_WORKER: LazyLock<BuiltinLog> =
342342
}),
343343
});
344344

345+
pub static MZ_COMPUTE_LIFECYCLE_EVENTS_PER_WORKER: LazyLock<BuiltinLog> =
346+
LazyLock::new(|| BuiltinLog {
347+
name: "mz_compute_lifecycle_events_per_worker",
348+
schema: MZ_INTROSPECTION_SCHEMA,
349+
oid: oid::LOG_MZ_COMPUTE_LIFECYCLE_EVENTS_PER_WORKER_OID,
350+
variant: LogVariant::Compute(ComputeLog::LifecycleEvent),
351+
access: vec![PUBLIC_SELECT],
352+
ontology: Some(Ontology {
353+
entity_name: "compute_lifecycle_event_per_worker",
354+
description: "Lifecycle events of each compute export, as observed by the worker \
355+
that logged them. Every event carries the wallclock instant it \
356+
occurred at, so durations between stages are differences of \
357+
`occurred_at`. The `installed`, `started` and `hydrated` events are \
358+
logged by every worker, since each worker hydrates its own fragment \
359+
of the dataflow. The write events are logged only by the worker that \
360+
maintains the sink frontier, so they appear once per export rather \
361+
than once per worker.",
362+
links: &const {
363+
[OntologyLink {
364+
name: "lifecycle_event_of",
365+
target: "compute_export_per_worker",
366+
properties: LinkProperties::MapsTo {
367+
source_column: "export_id",
368+
target_column: "export_id",
369+
via: None,
370+
from_type: Some(SemanticType::GlobalId),
371+
to_type: Some(SemanticType::GlobalId),
372+
note: None,
373+
},
374+
}]
375+
},
376+
column_semantic_types: &[("export_id", SemanticType::GlobalId)],
377+
}),
378+
});
379+
345380
pub static MZ_COMPUTE_OPERATOR_HYDRATION_STATUSES_PER_WORKER: LazyLock<BuiltinLog> =
346381
LazyLock::new(|| BuiltinLog {
347382
name: "mz_compute_operator_hydration_statuses_per_worker",

src/catalog/src/durable/transaction.rs

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1021,6 +1021,7 @@ impl<'a> Transaction<'a> {
10211021
LogVariant::Compute(ComputeLog::DataflowGlobal) => 31,
10221022
LogVariant::Compute(ComputeLog::OperatorHydrationStatus) => 32,
10231023
LogVariant::Compute(ComputeLog::PrometheusMetrics) => 33,
1024+
LogVariant::Compute(ComputeLog::LifecycleEvent) => 34,
10241025
};
10251026

10261027
let mut id: u64 = u64::from(cluster_variant) << 56;

src/compute-client/src/logging.rs

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -176,6 +176,8 @@ pub enum ComputeLog {
176176
ErrorCount,
177177
/// Hydration times of exported collections.
178178
HydrationTime,
179+
/// Lifecycle events of exported collections.
180+
LifecycleEvent,
179181
/// Hydration status of dataflow operators.
180182
OperatorHydrationStatus,
181183
/// Mappings from `GlobalId`/`LirId`` pairs to dataflow addresses.
@@ -370,6 +372,18 @@ impl LogVariant {
370372
.with_key(vec![0, 1])
371373
.finish(),
372374

375+
LogVariant::Compute(ComputeLog::LifecycleEvent) => RelationDesc::builder()
376+
.with_column("export_id", SqlScalarType::String.nullable(false))
377+
.with_column("worker_id", SqlScalarType::UInt64.nullable(false))
378+
.with_column("event", SqlScalarType::String.nullable(false))
379+
.with_column(
380+
"occurred_at",
381+
SqlScalarType::TimestampTz { precision: None }.nullable(false),
382+
)
383+
.with_column("reason", SqlScalarType::String.nullable(true))
384+
.with_column("details", SqlScalarType::Jsonb.nullable(true))
385+
.finish(),
386+
373387
LogVariant::Compute(ComputeLog::OperatorHydrationStatus) => RelationDesc::builder()
374388
.with_column("export_id", SqlScalarType::String.nullable(false))
375389
.with_column("lir_id", SqlScalarType::UInt64.nullable(false))

src/compute/src/compute_state.rs

Lines changed: 142 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -70,7 +70,7 @@ use uuid::Uuid;
7070

7171
use crate::arrangement::manager::{TraceBundle, TraceManager};
7272
use crate::logging;
73-
use crate::logging::compute::{CollectionLogging, ComputeEvent, PeekEvent};
73+
use crate::logging::compute::{CollectionLogging, ComputeEvent, LifecycleStage, PeekEvent};
7474
use crate::logging::initialize::LoggingTraces;
7575
use crate::metrics::{CollectionMetrics, WorkerMetrics};
7676
use crate::render::{LinearJoinSpec, StartSignal};
@@ -694,6 +694,7 @@ impl<'a> ActiveComputeState<'a> {
694694
object_id,
695695
logger,
696696
*dataflow_index,
697+
as_of.as_option().copied(),
697698
dataflow.import_ids(),
698699
);
699700
if starts_immediately {
@@ -884,12 +885,17 @@ impl<'a> ActiveComputeState<'a> {
884885
let mut collection = CollectionState::new(
885886
Rc::clone(&dataflow_index),
886887
is_subscribe_or_copy,
887-
as_of,
888+
as_of.clone(),
888889
metrics,
889890
);
890891

891-
let logging =
892-
CollectionLogging::new(id, logger.clone(), *dataflow_index, std::iter::empty());
892+
let logging = CollectionLogging::new(
893+
id,
894+
logger.clone(),
895+
*dataflow_index,
896+
as_of.as_option().copied(),
897+
std::iter::empty(),
898+
);
893899
// Log collections are never suspended and the controller marks them scheduled
894900
// implicitly, so no `Schedule` command ever arrives for them. Record their hydration
895901
// start here, or they would sit permanently in the illegal state of being hydrated
@@ -921,6 +927,8 @@ impl<'a> ActiveComputeState<'a> {
921927

922928
// Maintain a single allocation for `new_frontier` to avoid allocating on every iteration.
923929
let mut new_frontier = Antichain::new();
930+
// Same, for the frontier that measures dataflow progress.
931+
let mut hydration_frontier = Antichain::new();
924932

925933
for (&id, collection) in self.compute_state.collections.iter_mut() {
926934
// The compute protocol does not allow `Frontiers` responses for subscribe and copy-to
@@ -950,6 +958,36 @@ impl<'a> ActiveComputeState<'a> {
950958
.allows_reporting(&new_frontier)
951959
.then(|| new_frontier.clone());
952960

961+
// Collect the frontier that measures the dataflow's own progress, which is what
962+
// hydration is about.
963+
//
964+
// This is deliberately not the output frontier collected below. That folds in the
965+
// write frontier, which makes it a measure of durability rather than of dataflow
966+
// progress, and for a collection that sinks to persist it is not even uniform across
967+
// workers: the sink's `mint` operator maintains the shared sink frontier on one
968+
// elected worker and clears it on all the others, so the same dataflow would report
969+
// hydration at two different times depending on which worker's log you read.
970+
//
971+
// A collection with a compute frontier produces its output before writing it, so that
972+
// frontier is its progress. A collection without one produces its output *by* writing
973+
// it, an index into its own trace, so there the write frontier is the progress and
974+
// hydration coincides with durability.
975+
hydration_frontier.clear();
976+
match &collection.compute_probe {
977+
Some(probe) => {
978+
probe.with_frontier(|frontier| {
979+
hydration_frontier.extend(frontier.iter().copied())
980+
});
981+
}
982+
None => hydration_frontier.clone_from(&new_frontier),
983+
}
984+
985+
// Evaluate the lifecycle predicates here, while both frontiers are still in hand.
986+
// `new_frontier` is folded into the output frontier below, which loses the write
987+
// frontier this one is about.
988+
let hydrated = PartialOrder::less_than(&collection.as_of, &hydration_frontier);
989+
let written = PartialOrder::less_than(&collection.as_of, &new_frontier);
990+
953991
// Collect the output frontier and check for progress.
954992
//
955993
// By default, the output frontier equals the write frontier (which is still stored in
@@ -996,6 +1034,9 @@ impl<'a> ActiveComputeState<'a> {
9961034
.set_reported_output_frontier(ReportedFrontier::Reported(frontier.clone()));
9971035
}
9981036

1037+
collection.observe_hydration(hydrated);
1038+
collection.observe_writes(written);
1039+
9991040
let response = FrontiersResponse {
10001041
write_frontier: new_write_frontier,
10011042
input_frontier: new_input_frontier,
@@ -1209,6 +1250,12 @@ impl<'a> ActiveComputeState<'a> {
12091250
.set_reported_write_frontier(ReportedFrontier::Reported(new_frontier.clone()));
12101251
collection
12111252
.set_reported_input_frontier(ReportedFrontier::Reported(new_frontier.clone()));
1253+
// Only a batch upper measures progress. `DroppedAt` reports the empty
1254+
// antichain, which is the maximum of the order, so a subscribe cancelled while
1255+
// still hydrating would otherwise read as hydrated at the moment it is dropped.
1256+
let hydrated = matches!(response, SubscribeResponse::Batch(_))
1257+
&& PartialOrder::less_than(&collection.as_of, &new_frontier);
1258+
collection.observe_hydration(hydrated);
12121259
collection.set_reported_output_frontier(ReportedFrontier::Reported(new_frontier));
12131260
} else {
12141261
// Presumably tracking state for this subscribe was already dropped by
@@ -1998,6 +2045,21 @@ pub struct CollectionState {
19982045
logging: Option<CollectionLogging>,
19992046
/// Metrics tracked for this collection.
20002047
metrics: CollectionMetrics,
2048+
/// Whether this worker maintains the authoritative write frontier of this collection's sink.
2049+
///
2050+
/// A persist sink elects one worker to track the output shard's upper and clears the shared
2051+
/// frontier on all the others, so only the elected worker's copy carries write progress. The
2052+
/// write lifecycle stages are logged by that worker alone, which also makes them a single
2053+
/// observation per export rather than one per worker. False for collections whose output
2054+
/// frontier is not a persist upper at all, such as indexes and metric sinks.
2055+
pub owns_sink_frontier: bool,
2056+
/// Which lifecycle stages have been logged for this collection.
2057+
///
2058+
/// Stages are only ever added, never removed. Reconciliation resets the reported frontiers of
2059+
/// a retained dataflow, so without this the collection would look unhydrated again and re-log
2060+
/// a stage it already reported. The lifecycle relation is append-only, so a repeat would show
2061+
/// up as a duplicate row rather than being dropped.
2062+
logged_stages: BTreeSet<LifecycleStage>,
20012063
/// Send-side to transition a dataflow from read-only mode to read-write mode.
20022064
///
20032065
/// All dataflows start in read-only mode. Only after receiving a
@@ -2036,6 +2098,8 @@ impl CollectionState {
20362098
compute_probe: None,
20372099
logging: None,
20382100
metrics,
2101+
owns_sink_frontier: false,
2102+
logged_stages: BTreeSet::new(),
20392103
read_only_tx,
20402104
read_only_rx,
20412105
}
@@ -2094,13 +2158,87 @@ impl CollectionState {
20942158
}
20952159

20962160
/// Return whether this collection is hydrated.
2161+
///
2162+
/// This is the output-frontier reading, which folds in the write frontier and so reports
2163+
/// durability for a collection that sinks to persist. `observe_hydration` reports the
2164+
/// dataflow-progress reading instead. Both are wanted, and they differ for a materialized view
2165+
/// by the time its snapshot takes to reach persist.
20972166
fn hydrated(&self) -> bool {
20982167
match &self.reported_frontiers.output_frontier {
20992168
ReportedFrontier::Reported(frontier) => PartialOrder::less_than(&self.as_of, frontier),
21002169
ReportedFrontier::NotReported { .. } => false,
21012170
}
21022171
}
21032172

2173+
/// Log that this collection reached a lifecycle stage, unless it already reported it.
2174+
fn log_stage(&mut self, stage: LifecycleStage) {
2175+
if !self.logged_stages.insert(stage) {
2176+
return;
2177+
}
2178+
if let Some(logging) = &self.logging {
2179+
logging.log_lifecycle(stage);
2180+
}
2181+
}
2182+
2183+
/// Observe whether this collection's dataflow has progressed past its as-of, and log the
2184+
/// `hydrated` stage the first time it has.
2185+
///
2186+
/// The caller decides which frontier measures dataflow progress. See the comment at the call
2187+
/// site in `report_frontiers`. An empty as-of never hydrates, which is consistent with no
2188+
/// dataflow being created for one.
2189+
fn observe_hydration(&mut self, hydrated: bool) {
2190+
if hydrated {
2191+
self.log_stage(LifecycleStage::Hydrated);
2192+
}
2193+
}
2194+
2195+
/// Observe whether this collection's sink has written past its as-of, and log the write
2196+
/// lifecycle stages it has reached.
2197+
///
2198+
/// Only the worker that maintains the sink frontier reports these stages, which is what makes
2199+
/// them one observation per export rather than one per worker.
2200+
///
2201+
/// Nothing is reported before the dataflow has hydrated. Until then the sink has produced no
2202+
/// output, so read-only mode is not holding anything back, and reporting a block there would
2203+
/// make `write_unblocked - hydrated` negative in the common case rather than zero. Gating here
2204+
/// also keeps the stages ordered against `written`, which can otherwise arrive first:
2205+
/// `apply_refresh` rounds a `REFRESH` materialized view's frontier up to the next refresh time
2206+
/// before the dataflow has computed anything, so its sink writes an empty batch for the
2207+
/// pre-refresh window and the shard's upper passes the as-of while the dataflow is still
2208+
/// hydrating.
2209+
///
2210+
/// NOTE: `written` is derived from the output shard's upper, which is a property of the shard
2211+
/// and not of this replica. The as-of is bounded to one step below that upper for a non-empty
2212+
/// storage export (`as_of_selection::apply_downstream_storage_constraints`), so for a shard
2213+
/// that already holds data the predicate is true from the moment the dataflow is installed. A
2214+
/// replica that may not write can therefore never be the one that advanced it, which is why
2215+
/// the stage is withheld while writes are blocked. Reporting it there would attribute another
2216+
/// writer's progress to this replica and put `written` before `write_unblocked`.
2217+
fn observe_writes(&mut self, written: bool) {
2218+
if !self.owns_sink_frontier || !self.logged_stages.contains(&LifecycleStage::Hydrated) {
2219+
return;
2220+
}
2221+
2222+
let read_only = *self.read_only_rx.borrow();
2223+
if read_only {
2224+
self.log_stage(LifecycleStage::WriteBlockedReadOnly);
2225+
return;
2226+
}
2227+
2228+
if self
2229+
.logged_stages
2230+
.contains(&LifecycleStage::WriteBlockedReadOnly)
2231+
{
2232+
// Only report having been unblocked if we reported being blocked. A collection whose
2233+
// writes were allowed before we first observed it was never seen to wait.
2234+
self.log_stage(LifecycleStage::WriteUnblocked);
2235+
}
2236+
2237+
if written {
2238+
self.log_stage(LifecycleStage::Written);
2239+
}
2240+
}
2241+
21042242
/// Allow writes for this collection.
21052243
fn allow_writes(&self) {
21062244
info!(

0 commit comments

Comments
 (0)