feat(log-store): add object store WAL metrics and the conditional-create fault matrix (#9475)

* feat(log-store): add object store WAL metrics and the conditional-create fault matrix

Export the remaining fifteen metrics of the object store WAL under
greptime_logstore_object_store_wal_: the write path timers and object
shape histograms, created objects, the indexed object and byte gauges,
recovery and read timers, recovered objects, create conflicts and
failures, poisoned stores, and stalled appends with their wait.

Add a table-driven fault matrix that drives every outcome of a
conditional create and of the start object through the store and asserts
the failed waiters, the poison, the sequence, both indexed gauges at the
failure, the movement of every metric, and what a read sees afterwards.
The test fails if a row of the failure matrix has no case. Every test of
the store module now holds one lock, since the metrics are process-wide.

Signed-off-by: jeremyhi <fengjiachun@gmail.com>

* fix(log-store): count every conditional create of the object store WAL

Count the outcome of the start object's create, and count a create
that met a different object as a conflict before the epoch of that
object is read, so a failed epoch read no longer hides the conflict.

The fault matrix waits until no store actor of an earlier test is
alive, checks that a poisoned read returns the recorded terminal error,
and covers a conflicting object whose header cannot be read.

Signed-off-by: jeremyhi <fengjiachun@gmail.com>

---------

Signed-off-by: jeremyhi <fengjiachun@gmail.com>

src/log-store/src/metrics.rs

@@ -111,4 +111,171 @@ lazy_static! {
         "object store logstore failed object deletes total",
     )
     .unwrap();
+
+    /// How long an object of the object store logstore takes to become durable
+    /// once its batch is sealed, sampled for every conditional create that
+    /// succeeds, an identical retry included. The time runs from the seal, so
+    /// it includes any wait for a create slot and, in the `enqueued` mode,
+    /// every repeated attempt and the delay before it.
+    ///
+    /// A create is a few milliseconds on a local object store and tens of
+    /// milliseconds on a cloud one, so the buckets start at 1ms and reach 8s.
+    pub static ref METRIC_OBJECT_STORE_WAL_SEAL_TO_DURABLE_SECONDS: Histogram = register_histogram!(
+        "greptime_logstore_object_store_wal_seal_to_durable_seconds",
+        "object store logstore seconds from sealing a batch to the success of its conditional create, slot waits and retries included",
+        exponential_buckets(0.001, 2.0, 14).unwrap(),
+    )
+    .unwrap();
+
+    /// How long an append of the object store logstore waits for its
+    /// acknowledgement in the `durable` mode, which is the write latency a
+    /// caller sees.
+    ///
+    /// The wait is one seal plus every earlier object plus one create, so with
+    /// the default 100ms flush interval it sits in the tens of milliseconds;
+    /// the buckets straddle that and leave room for a stalled uploader.
+    pub static ref METRIC_OBJECT_STORE_WAL_APPEND_ACK_SECONDS: Histogram = register_histogram!(
+        "greptime_logstore_object_store_wal_append_ack_seconds",
+        "object store logstore seconds an append waits for its acknowledgement in the durable mode",
+        exponential_buckets(0.002, 2.0, 14).unwrap(),
+    )
+    .unwrap();
+
+    /// How large the objects of the object store logstore are, which says
+    /// whether batches seal on size or on the flush interval.
+    ///
+    /// The buckets are powers of two from 1KiB, the size of a timer-sealed
+    /// batch of one small entry, to 16MiB, twice the 8MiB default batch size,
+    /// which is a threshold rather than an upper bound.
+    pub static ref METRIC_OBJECT_STORE_WAL_OBJECT_BYTES: Histogram = register_histogram!(
+        "greptime_logstore_object_store_wal_object_bytes",
+        "object store logstore bytes of each object sealed",
+        exponential_buckets(1024.0, 2.0, 15).unwrap(),
+    )
+    .unwrap();
+
+    /// How many entries the objects of the object store logstore hold, which
+    /// says how many writes one request amortises.
+    ///
+    /// The largest finite bucket is 2^20, the position limit of one region in
+    /// one object. An object holds the entries of many regions, so its total
+    /// can pass that; such an object falls in the overflow bucket.
+    pub static ref METRIC_OBJECT_STORE_WAL_OBJECT_ENTRIES: Histogram = register_histogram!(
+        "greptime_logstore_object_store_wal_object_entries",
+        "object store logstore entries of each object sealed",
+        exponential_buckets(1.0, 4.0, 11).unwrap(),
+    )
+    .unwrap();
+
+    /// Counter of conditional creates of the object store logstore that
+    /// succeeded, an identical retry that found its own object included. A
+    /// create that failed is counted in the create failure or conflict counter
+    /// instead.
+    pub static ref METRIC_OBJECT_STORE_WAL_CREATED_OBJECTS_TOTAL: IntCounter = register_int_counter!(
+        "greptime_logstore_object_store_wal_created_objects_total",
+        "object store logstore conditional creates that succeeded, identical retries included",
+    )
+    .unwrap();
+
+    /// Number of objects the object store logstore has indexed, which is what
+    /// a recovery of the prefix would have to read.
+    pub static ref METRIC_OBJECT_STORE_WAL_INDEXED_OBJECTS: IntGauge = register_int_gauge!(
+        "greptime_logstore_object_store_wal_indexed_objects",
+        "object store logstore objects currently indexed",
+    )
+    .unwrap();
+
+    /// Bytes of the objects the object store logstore has indexed, which is
+    /// what the WAL occupies under its prefix.
+    pub static ref METRIC_OBJECT_STORE_WAL_INDEXED_BYTES: IntGauge = register_int_gauge!(
+        "greptime_logstore_object_store_wal_indexed_bytes",
+        "object store logstore bytes currently indexed",
+    )
+    .unwrap();
+
+    /// How long a recovery of the object store logstore that succeeded took to
+    /// rebuild its catalog, which is the part of a restart the WAL is
+    /// responsible for. A recovery that was abandoned records nothing.
+    ///
+    /// Recovery reads a few small ranges per object, so the buckets run from
+    /// 10ms, an empty prefix, to minutes on a prefix with many objects.
+    pub static ref METRIC_OBJECT_STORE_WAL_RECOVERY_SECONDS: Histogram = register_histogram!(
+        "greptime_logstore_object_store_wal_recovery_seconds",
+        "object store logstore seconds spent by a recovery that succeeded",
+        exponential_buckets(0.01, 3.0, 10).unwrap(),
+    )
+    .unwrap();
+
+    /// Counter of objects a recovery of the object store logstore that
+    /// succeeded read footers from, which is what its time is spent on. It
+    /// counts the objects of the same recoveries the timer above measures, so
+    /// an abandoned one contributes to neither.
+    pub static ref METRIC_OBJECT_STORE_WAL_RECOVERED_OBJECTS_TOTAL: IntCounter = register_int_counter!(
+        "greptime_logstore_object_store_wal_recovered_objects_total",
+        "object store logstore objects read by a recovery that succeeded total",
+    )
+    .unwrap();
+
+    /// How long a read stream of the object store logstore took to serve the
+    /// replay of one region, recorded once the stream has been read to its
+    /// end; one that fails or is dropped part way records nothing.
+    ///
+    /// A read fetches one segment per object of the region, so the buckets run
+    /// from 5ms, a region with nothing to replay, to minutes.
+    pub static ref METRIC_OBJECT_STORE_WAL_READ_SECONDS: Histogram = register_histogram!(
+        "greptime_logstore_object_store_wal_read_seconds",
+        "object store logstore seconds spent serving a region read that ran to its end",
+        exponential_buckets(0.005, 3.0, 10).unwrap(),
+    )
+    .unwrap();
+
+    /// Counter of conditional creates of the object store logstore that found
+    /// an object with different content. In the `durable` mode an object of an
+    /// earlier epoch fails the batch like a transient failure; any other
+    /// conflict poisons the store.
+    pub static ref METRIC_OBJECT_STORE_WAL_CREATE_CONFLICTS_TOTAL: IntCounter = register_int_counter!(
+        "greptime_logstore_object_store_wal_create_conflicts_total",
+        "object store logstore conflicting conditional creates total",
+    )
+    .unwrap();
+
+    /// Counter of conditional creates of the object store logstore the object
+    /// store did not confirm, which fail the appends behind them in the
+    /// `durable` mode and are repeated in the `enqueued` mode.
+    pub static ref METRIC_OBJECT_STORE_WAL_CREATE_FAILURES_TOTAL: IntCounter = register_int_counter!(
+        "greptime_logstore_object_store_wal_create_failures_total",
+        "object store logstore transient conditional create failures total",
+    )
+    .unwrap();
+
+    /// Counter of object store logstores that hit an error they cannot recover
+    /// from, after which every operation of the store fails until it reopens.
+    pub static ref METRIC_OBJECT_STORE_WAL_POISONED_TOTAL: IntCounter = register_int_counter!(
+        "greptime_logstore_object_store_wal_poisoned_total",
+        "object store logstores poisoned total",
+    )
+    .unwrap();
+
+    /// Counter of appends the object store logstore held back because the
+    /// unpersisted backlog reached a threshold in the `enqueued` mode, which
+    /// says the write rate is above what the uploads sustain.
+    pub static ref METRIC_OBJECT_STORE_WAL_STALLED_APPENDS_TOTAL: IntCounter = register_int_counter!(
+        "greptime_logstore_object_store_wal_stalled_appends_total",
+        "object store logstore appends stalled by the backlog thresholds total",
+    )
+    .unwrap();
+
+    /// How long such an append stays held back, until it is admitted or until
+    /// it is refused, a stop, a terminal error or the teardown of the store
+    /// releasing it included, which is the latency the `enqueued` mode pays
+    /// once the backlog is at a threshold.
+    ///
+    /// A stalled append waits for one upload to complete, so the buckets run
+    /// from 5ms to half a minute of a struggling object store.
+    pub static ref METRIC_OBJECT_STORE_WAL_STALLED_APPEND_SECONDS: Histogram = register_histogram!(
+        "greptime_logstore_object_store_wal_stalled_append_seconds",
+        "object store logstore seconds a stalled append is held back before it is admitted or refused",
+        exponential_buckets(0.005, 3.0, 9).unwrap(),
+    )
+    .unwrap();
 }

src/log-store/src/object_store_wal/format.rs

@@ -43,7 +43,6 @@ const SEGMENT_HEADER_LEN: usize = 8 + 4;
 /// offset, segment length and segment CRC32.
 pub(crate) const FOOTER_ENTRY_LEN: usize = 8 + 8 + 8 + 4 + 8 + 8 + 4;
 /// Length of the entry count the footer starts with.
-#[cfg(test)]
 const FOOTER_COUNT_LEN: usize = 4;
 
 /// Header of a WAL object.
@@ -191,7 +190,6 @@ pub(crate) fn encode_object(header: Header, records: &[Record]) -> Result<Encode
 /// Returns the length of the object whose footer is `footer`, derived from the
 /// layout: the segments tile the body after the header, and the footer, which
 /// holds an entry count and one entry per segment, and the trailer follow them.
-#[cfg(test)]
 pub(crate) fn object_len(footer: &[FooterEntry]) -> u64 {
     let segments = footer.iter().map(|entry| entry.segment_len).sum::<u64>();
     let framing = HEADER_LEN + FOOTER_COUNT_LEN + footer.len() * FOOTER_ENTRY_LEN + TRAILER_LEN;