jerryshao commented on code in PR #13388:
URL: https://github.com/apache/gravitino/pull/13388#discussion_r4069103083
##########
core/src/main/java/org/apache/gravitino/storage/relational/EntityChangeLogPoller.java:
##########
@@ -198,8 +216,31 @@ private synchronized void doPollChanges() {
@Nullable
private BatchDelivery fetchNextDelivery() {
+ long fetchStartNanos = System.nanoTime();
List<EntityChangeRecord> changes = fetchEntityChanges();
+ // The tail is for observability only. A failed sample must not suppress
delivery of rows
+ // already fetched successfully or hold the cursor back.
+ @Nullable Long dbTailId = null;
+ try {
+ dbTailId =
+ getOrDefault(
+ SessionUtils.getWithoutCommit(
+ EntityChangeLogMapper.class,
EntityChangeLogMapper::selectMaxChangeId));
+ metrics.setDbTailId(dbTailId);
+ } catch (RuntimeException e) {
+ if (handleInterruptIfAny(e, "Entity change log tail sample")) {
+ throw e;
+ }
+ LOG.warn("Could not sample entity change log tail; retaining the
previous gauge value", e);
Review Comment:
[Important] Making the tail sample best effort fixed the dropped-batch
problem, but it also removed the last metric that showed the tail query is
broken — in an observability PR, that is the signal an operator most needs.
When `selectMaxChangeId` keeps failing while `selectEntityChanges` keeps
working, this catch swallows it and the cycle continues:
`metrics.pollSucceeded(...)` on line 236 still refreshes
`lastSuccessfulPollMs`, so `seconds-since-last-successful-poll` stays fresh,
and `pollFailed()` is never reached, so `poll-failures-total` stays 0.
Meanwhile `advanceCursor` (line 326) keeps moving `cursor-id` forward while
`dbTailId` is frozen at its last good sample, so `record-lag`, defined as
`Math.max(0, dbTailId.get() - cursorId.get())` at
EntityChangeLogMetricsSource.java:47, goes negative and clamps to a permanent
0. Every gauge and counter in the new source then reads perfectly healthy, and
`db-tail-id` sits silently *below* `cursor-id` — which is exactly the
comparison docs/metrics.md:102 tells operators to make first during an
incident. A `LOG.warn` is the only remaining trace.
Cheapest fix: add a counter next to the warn, e.g.
`metrics.tailSampleFailed()` backed by a `tail-sample-failures-total` counter,
document it in the metrics table, and say in the table entry for `record-lag`
that the value is only meaningful while the tail sample is succeeding.
Returning the gauge to a sentinel such as `-1` on failure would work too, but a
counter keeps the existing gauges monotone and is easy to alert on.
Verified by: read EntityChangeLogPoller.java:218-236, 193-206 and 323-327 on
this checkout — `pollSucceeded` and `advanceCursor` are both reached on this
path and `metrics.pollFailed()` is unreachable from it; read the `record-lag`
gauge definition at EntityChangeLogMetricsSource.java:47 and the incident
paragraph at docs/metrics.md:102-103. `grep -rn "record-lag" core/src/test`
confirms no test exercises the stale-tail state.
##########
docs/metrics.md:
##########
@@ -71,3 +71,37 @@
gravitino_catalog_datasource_idle_connections{provider="jdbc",metalake="test_met
gravitino_catalog_datasource_active_connections{provider="jdbc",metalake="test_metalake",catalog="test_catalog",}
0.0
gravitino_catalog_datasource_max_connections{provider="jdbc",metalake="test_metalake",catalog="test_catalog",}
10.0
```
+
+#### Entity Change Log Metrics
+
+The `entity-change-log` source exposes each server's change-log processing
state through JMX and
+`/prometheus/metrics`. For example, `entity-change-log.record-lag` in the
metrics registry becomes
+`entity_change_log_record_lag` in Prometheus. Gauges read only in-memory
values; the poller samples
+the database tail once per cycle. If only the tail sample fails, delivery
continues and the tail
+value remains at its last successful sample.
+
+| Metric suffix | Type and unit
| Meaning
|
+| ------------------------------------------------------------ |
------------------------ |
------------------------------------------------------------------------------------------------------------------------
|
+| `db-tail-id`, `cursor-id` | gauge, change
ID | Latest sampled database ID and last delivered ID on this server.
|
+| `record-lag` | gauge,
records | Sampled tail minus cursor; this may briefly grow during a
poll. |
+| `seconds-since-last-successful-poll` | gauge,
seconds | Time since a successful database poll, including an empty
result; `-1` before the first poll. |
+| `poll-failures-total` | counter,
failures | Failed poll cycles.
|
+| `listener-failures-total`, `listener-failures.<class>-total` | counter,
failures | Total failures and failures by registered listener class.
|
+| `records-fetched-total`, `records-delivered-total` | counter,
records | Rows fetched and rows delivered successfully to listeners;
one row delivered to two listeners counts twice as delivered. |
+| `records-delivered.<class>-total` | counter,
records | Successful deliveries by listener class. Lambda and anonymous
listeners share the `anonymous` bucket. |
+| `records-applied-total` | counter,
invalidations | Targeted entity-cache invalidations completed successfully;
malformed rows and fallback clears do not count. |
+| `batch-size-records` | histogram,
records | Number of rows fetched per successful poll, including empty
polls. |
+| `poll-duration` | timer,
duration | End-to-end poll-cycle duration.
|
+| `invalidation-failures-total`, `fallback-clears-total` | counter,
failures/clears | Failed targeted entity-cache invalidations and successful
full-cache recovery clears. |
+
+The poller delivers each batch once and has no pending or retry state. A
failed listener must
+recover locally; its failure counter and log identify the affected listener.
The debug logs use
+`entityChangeLog` fields to trace an append, poll, delivery, and invalidation.
Append logs mean the
+row was added to the current transaction, not that the transaction committed.
+
+For an incident, compare `db-tail-id` with `cursor-id` on the affected server.
A growing
+`record-lag` together with an increasing poll age or `poll-failures-total`
points to polling trouble.
Review Comment:
[Nit] This incident playbook is now slightly wrong for the failure mode the
same commit introduced. After a tail-sample failure, delivery continues and the
cursor advances while `db-tail-id` stays frozen, so "compare `db-tail-id` with
`cursor-id`" can show the tail *below* the cursor, and the "growing
`record-lag`" cue never fires because the gauge clamps to 0
(EntityChangeLogMetricsSource.java:47).
The note added at line 80 already tells operators the tail value can be
stale; worth carrying that into this paragraph too — one clause saying that a
`db-tail-id` below `cursor-id` means the tail sample itself is failing and that
`record-lag` should be read only while the tail is fresh. This pairs with the
counter suggested on EntityChangeLogPoller.java.
Verified by: read docs/metrics.md:74-107 and
EntityChangeLogMetricsSource.java:45-54 on this checkout.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
