You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@cloudberry.apache.org by "leborchuk (via GitHub)" <gi...@apache.org> on 2026/09/04 10:14:18 UTC
[D] [Ideas] Add instrumentation and latency metrics to the Anser subsystem [cloudberry]
GitHub user leborchuk created a discussion: [Ideas] Add instrumentation and latency metrics to the Anser subsystem
### Description
# Description
Anser (`gpcontrib/anser/`) is a runtime pub/sub facility: producer nodes on the
segments publish a bloom filter over a join-build key, the coordinator unions
the parts, and consumer nodes on the segments receive it and prune probe rows.
See `gpcontrib/anser/README.md` for the architecture before starting.
Today we can see *what* the filter did (`Rows Removed by Bloom Filter` in
`EXPLAIN ANALYZE`) but nothing about *what it cost*. A producer blocks until the
coordinator acknowledges its part; a consumer blocks until the payload is
delivered. If those waits are expensive, the filter can be a net loss and we
currently have no way to tell.
## Goal
Make every wait and every queueing delay in Anser measurable, both
per query (in `EXPLAIN`) and cluster-wide (in shared memory).
## Definition of done
- [ ] `EXPLAIN (ANALYZE, VERBOSE)` shows producer and consumer wait count and
wait time, **including for segment-executed nodes**.
- [ ] `SELECT * FROM anser.stats()` shows queue time, service-cycle latency,
and the histograms; `anser.stats_reset()` works.
- [ ] `SELECT * FROM anser.session_stats()` reflects the current session only.
- [ ] Regression tests pass and contain no timing-dependent expected values.
- [ ] `README.md` gains a "Metrics" section: every field, its unit, and where it
is measured.
- [ ] No new LWLock acquisitions on the data path; no per-tuple timing calls.
- [ ] Core (`src/`) is untouched.
## What to measure
There are two distinct vantage points. Do not mix them up — this is the single
most important thing to understand before writing code.
| Vantage point | Who waits | Where the wait actually happens |
| --- | --- | --- |
| **Executor node** (segment or coordinator) | the query | segment: the libpq round trip in `AnserClientPublish` / `AnserClientConsumeWait` (`src/anserclient.c`); coordinator: the direct calls `AnserPublish` / `AnserWaitProducersRegistered` + `AnserWaitReady` + `AnserConsumeReady` (`src/anser.c`) |
| **Coordinator internals** | the QD backend serving a segment, and the two background workers | `AnserWaitSubmissionAck` (`src/anser.c:906`), `AnserWaitSlotResult` (`src/anser.c:1110`), `AnserGatherServiceCycle` (`src/anser.c:1235`), `AnserSendServiceCycle` (`src/anser.c:1433`) |
The first belongs in `EXPLAIN`. The second belongs in shared-memory counters,
because no single backend sees it.
## Implementation
Suggest three changes in this order. Each is independently reviewable and testable.
### Change 1 — per-node wait time in EXPLAIN
- [ ] Time the publish call in the producer node and the receive call in the
consumer node. Record, per node: **number of waits**, **total wait time**,
and **longest single wait**.
- Producer: `AnserProducePublishPart()` in `src/anserbloomproduce.c` — it picks
the transport by role, so wrapping it covers both segment and coordinator.
- Consumer: `ExecAnserBloomFilterConsume()` in `src/anserbloomconsume.c`.
- Store the accumulators in `AnserBloomProduceScanState` /
`AnserBloomConsumeScanState` (`src/anserplanexec.c:81` and `:95`).
- [ ] Print them from `anser_produce_explain()` (`src/anserplanexec.c:422`) and
`anser_consume_explain()` (`:636`), gated on `es->analyze` (there is
nothing to print without execution) and shown only at
`EXPLAIN (ANALYZE, VERBOSE)` — i.e. `es->analyze && es->verbose`.
Use `ExplainPropertyFloat("Anser Wait Time", "ms", ...)` and
`ExplainPropertyInteger("Anser Waits", NULL, ...)`.
**The trap you must handle.** A field you add to the node state on a *segment*
does **not** reach the QD. Read the comment at `src/anserplanexec.c:583-588`:
the existing code deliberately uses `InstrCountFiltered1/2` because only the
fixed fields of `CdbExplain_StatInst` (`src/backend/commands/explain_gp.c:44`)
travel back. Your new timers are not in that struct.
The supported escape hatch is the per-node *extra text* channel, which is how
`Hash` reports `Extra Text: (seg2) Hash chain length ...`:
- `PlanState.cdbexplainbuf` and `PlanState.cdbexplainfun`
(`src/include/nodes/execnodes.h:1152-1153`)
- collected on the segment by `cdbexplain_collectExtraText()`
(`src/backend/commands/explain_gp.c:1308`) and shipped to the QD
- **copy the pattern from `src/backend/executor/nodeRuntimeFilter.c:174-177`** —
it is the closest existing analogue (a runtime-filter node doing exactly this)
So: allocate `cdbexplainbuf` in `*_begin` when `estate->es_instrument` is set,
install a `cdbexplainfun` that appends your numbers, and the QD will show them
as `Extra Text` per segment. **No core change is needed** — if you find yourself
editing anything under `src/`, stop and re-read this paragraph.
### Change 2 — subsystem-wide counters and latency histograms in shared memory
- [ ] Add a stats block to Anser's shared memory. Either extend `AnserControl`
(`include/anser.h`) or add a separate struct; account for it in
`AnserShmemSize()` and initialize it in `AnserShmemInit()`
(`src/anser.c`), exactly as the existing structures do.
- [ ] Use `pg_atomic_uint64` (`src/include/storage/atomics.h`) for every counter
and bucket, and update them **without** taking `AnserChannelLock` /
`AnserRingLock`. These are on the data path; adding lock traffic for
metrics would change what we are trying to measure.
- [ ] Measure, at minimum:
| Metric | Where |
| --- | --- |
| time a part waits in the submission queue (enqueue → gather picks it up) | stamp the time in `AnserEnqueueSubmission()` (`src/anser.c:860`), read it in `AnserGatherServiceCycle()` (`:1235`) — add a field to `AnserSubmissionEntry` |
| time a consumer slot waits for delivery (register → send stamps payload) | stamp in `AnserRegisterWaitSlot()` (`:1077`), read in `AnserSendServiceCycle()` (`:1433`) — add a field to `AnserWaitSlot` |
| producer ack wait, on the QD side | `AnserWaitSubmissionAck()` (`:906`) |
| consumer delivery wait, on the QD side | `AnserWaitSlotResult()` (`:1110`) |
| background worker cycle duration, per service | around the `AnserGatherServiceCycle()` / `AnserSendServiceCycle()` calls in `AnserServiceLoop()` (`src/anserservice.c`) |
| counts: parts submitted / accepted / rejected, channels cancelled by timeout, consumers delivered / cancelled | the same call sites |
- [ ] Histogram design: fixed power-of-two microsecond buckets, e.g. 20 buckets
covering `<1µs, <2µs, ... , <512ms, >=512ms`. Compute the bucket with
`pg_leftmost_one_pos64()` (`src/include/port/pg_bitutils.h`) — no loops, no
floating point. Keep the bucket count a compile-time constant; the array
lives in fixed shared memory sized at postmaster start.
- [ ] Use `instr_time` for all timing (`src/include/portability/instr_time.h`:
`INSTR_TIME_SET_CURRENT`, `INSTR_TIME_SUBTRACT`, `INSTR_TIME_GET_MICROSEC`).
Do **not** use `GetCurrentTimestamp()` for durations.
**Accuracy caveat to document in the code:** the wait loops sleep in slices
(`ANSER_WAIT_POLL_INTERVAL_MS` = 10 ms, `ANSER_WAIT_LATCH_TIMEOUT_MS` = 1000 ms,
`ANSER_SERVICE_WAKEUP_INTERVAL_MS` = 1000 ms — see `include/anser.h`). Measure
wall time across the *whole* wait call, never by counting loop iterations, and
note in a comment that sub-poll-interval waits are quantized.
### Change 3 — per-session stats and the user-facing view
- [ ] Accumulate this backend's Anser activity in a plain `static` struct in
backend-local memory (no atomics, no locks — it is private).
- [ ] Flush it into the shared-memory totals once per query from an
`ExecutorEnd_hook` (`src/include/executor/executor.h:108`). Install it in
`_PG_init()` (`src/anserinit.c`) and **chain the previous hook** the same
way `anser_planner()` chains `prev_planner_hook` — copy that pattern.
- [ ] Expose the numbers:
- `anser.stats()` — set-returning function over the shared totals and the
histogram (one row per bucket, or one row per metric with the histogram as
an array; your call, document it), plus a matching view.
- `anser.session_stats()` — the backend-local numbers.
- `anser.stats_reset()` — zero the shared block; superuser only.
- [ ] Ship this as an **upgrade script**: add `anser--1.0--1.1.sql`, bump
`default_version` in `anser.control`, and add both to `DATA` in the
`Makefile`. Do not edit `anser--1.0.sql` in place — installed clusters
already have 1.0.
## Testing
- [ ] Extend `gpcontrib/anser/sql/anser_test.sql` (+ `expected/anser_test.out`).
- [ ] **Never put a measured time or a histogram bucket count in expected
output** — the tests would fail randomly. Assert properties instead:
`anser_test_...() > 0`, `total_waits` increased after a known round trip,
`stats_reset()` zeroes things. Return booleans from C test helpers
(`src/anser_test.c`) rather than printing numbers.
- [ ] For the `EXPLAIN` part, prefer asserting on plan *shape* — a raw
`EXPLAIN (ANALYZE, VERBOSE)` in expected output is unstable. If you must,
filter the output through a query that checks only that the property is
present.
- [ ] Run: `make -C gpcontrib/anser install && make -C gpcontrib/anser installcheck`
(the `installcheck` target arms the cluster itself). Requires
`shared_preload_libraries='anser'`, `anser.enable=on`, and
`CREATE EXTENSION anser` in the test database.
### What I expect from code
#### `EXPLAIN (ANALYZE, VERBOSE)` — the normal case
Three segments, `anser_rf_build` (200 rows) joined to `anser_rf_probe`
(2000 rows), the filter working as intended:
```
EXPLAIN (ANALYZE, VERBOSE, COSTS OFF)
SELECT b.name, p.payload
FROM anser_rf_build b JOIN anser_rf_probe p ON b.id = p.id;
Gather Motion 3:1 (slice1; segments: 3) (actual time=38.412..39.104 rows=200 loops=1)
Output: b.name, p.payload
-> Hash Join (actual time=35.881..36.402 rows=67 loops=1)
Output: b.name, p.payload
Hash Cond: (p.id = b.id)
-> Custom Scan (Anser Bloom Consumer) (actual time=31.902..33.114 rows=73 loops=1)
Output: p.id, p.payload
Bloom Filter Size: 1048576 bytes
Bloom Filter Stats: memory=1024kB checked=667 rejected=594
Rows Removed by Bloom Filter: 594
Anser Waits: 1
Anser Wait Time: 31.774 ms
Anser Max Wait: 31.774 ms
Extra Text: (seg0) Anser consumer: waits=1 total=31.774ms max=31.774ms registration=0.412ms delivery=31.362ms transport=libpq
-> Seq Scan on public.anser_rf_probe p (actual time=0.021..0.204 rows=667 loops=1)
Output: p.id, p.payload
-> Hash (actual time=2.510..2.511 rows=67 loops=1)
Output: b.name, b.id
Buckets: 262144 Batches: 1 Memory Usage: 2049kB
-> Redistribute Motion 3:3 (slice2; segments: 3) (actual time=1.884..2.301 rows=67 loops=1)
Output: b.name, b.id
Hash Key: b.id
-> Custom Scan (Anser Bloom Producer) (actual time=0.031..12.902 rows=67 loops=1)
Output: b.name, b.id
Bloom Filter Size: 1048576 bytes
Bloom Filter Stats: memory=1024kB
Anser Waits: 1
Anser Wait Time: 12.418 ms
Anser Max Wait: 12.418 ms
Extra Text: (seg1) Anser producer: waits=1 total=12.418ms max=12.418ms parts=1 bytes=1048640 transport=libpq
-> Seq Scan on public.anser_rf_build b (actual time=0.014..0.098 rows=67 loops=1)
Output: b.name, b.id
Planning Time: 4.221 ms
(slice0) Executor memory: 84K bytes.
(slice1) Executor memory: 3204K bytes avg x 3 workers, 3210K bytes max (seg0). Work_mem: 2049K bytes max.
(slice2) Executor memory: 412K bytes avg x 3 workers, 412K bytes max (seg1).
Memory used: 128000kB
Optimizer: Postgres query optimizer
Execution Time: 39.884 ms
```
Read this example carefully — it encodes several requirements:
- **Three summary properties per node**, in this order: `Anser Waits`
(integer), `Anser Wait Time` (ms), `Anser Max Wait` (ms). Emit them via
`ExplainPropertyInteger` / `ExplainPropertyFloat` so JSON/YAML/XML output
formats work for free — never `appendStringInfo` into the plan text.
- **The `Extra Text` line is the per-segment breakdown** shipped through
`cdbexplainbuf` (see the main issue). The summary properties above it are the
winning segment's values, exactly like every other per-node MPP statistic;
`Extra Text` is where a specific segment's detail shows up. Keep it one line,
`key=value` pairs, no line wrapping.
- **The consumer's wait splits into two phases**: `registration` (waiting for
producers to announce themselves) and `delivery` (waiting for the payload
after that). They come from different code paths and behave differently
under load, so report them separately.
- **`transport=libpq` vs `transport=shmem`** tells you whether the node ran on
a segment (libpq round trip to the QD) or coordinator-local (direct shared
memory). Without it you cannot interpret the numbers at all.
- **Where the time lands is not symmetric.** The producer publishes after its
child is exhausted, so its wait shows up in the node's *last* tuple time
(`0.031..12.902`). The consumer must receive before it can return anything,
so its wait shows up in the *first* tuple time (`31.902..`). Do not "fix"
this; it is the truth about when each side blocks.
- The consumer emits 73 rows but the join emits 67: those 6 are bloom false
positives. The filter is allowed to pass rows that do not join — it must never
reject one that does.
#### `EXPLAIN (ANALYZE)` without VERBOSE — unchanged
The new lines are VERBOSE-only. Plain `ANALYZE` keeps exactly today's output:
```
-> Custom Scan (Anser Bloom Consumer) (actual time=31.902..33.114 rows=73 loops=1)
Bloom Filter Size: 1048576 bytes
Bloom Filter Stats: memory=1024kB checked=667 rejected=594
Rows Removed by Bloom Filter: 594
```
#### `EXPLAIN (ANALYZE, VERBOSE)` — the case this feature exists for
A producer never published (crash, or a segment that produced no rows and was
cancelled), the channel hit the produce deadline, and the consumer waited
`anser.timeout_ms` for nothing before failing open. The query is still correct —
just slower than it would have been with the feature off, which is precisely
what we currently cannot see:
```
-> Custom Scan (Anser Bloom Consumer) (actual time=1002.774..1003.918 rows=667 loops=1)
Output: p.id, p.payload
Bloom Filter Size: 1048576 bytes
Bloom Filter Stats: memory=1024kB (no filter received: cancelled)
Anser Waits: 1
Anser Wait Time: 1002.601 ms
Anser Max Wait: 1002.601 ms
Extra Text: (seg2) Anser consumer: waits=1 total=1002.601ms max=1002.601ms registration=1000.118ms delivery=0.000ms result=cancelled transport=libpq
```
Note `rows=667` — every probe row passed, no pruning happened, and 1 second was
spent waiting. A `result=` field distinguishing `delivered` / `cancelled` /
`timeout` is required for exactly this reason.
#### `anser.stats()` — the shared-memory side (PR 2/3)
One row per metric, histogram buckets as an array so a single query is readable:
```
SELECT metric, count, total_ms, max_ms, p50_ms, p99_ms FROM anser.stats();
metric | count | total_ms | max_ms | p50_ms | p99_ms
-----------------------------+-------+----------+--------+--------+--------
producer_ack_wait | 1284 | 15012.44 | 84.12 | 8.19 | 65.53
submission_queue_time | 1284 | 612.08 | 16.38 | 0.26 | 4.09
consumer_registration_wait | 428 | 4118.72 | 131.07 | 4.09 | 131.07
consumer_delivery_wait | 428 | 12844.16 | 262.14 | 16.38 | 262.14
send_slot_queue_time | 428 | 131.07 | 2.05 | 0.13 | 1.02
gather_cycle | 18422 | 921.60 | 8.19 | 0.03 | 0.52
send_cycle | 18422 | 755.20 | 4.09 | 0.02 | 0.26
(7 rows)
SELECT metric, buckets FROM anser.stats() WHERE metric = 'consumer_delivery_wait';
metric | buckets
------------------------+--------------------------------------------------
consumer_delivery_wait | {0,0,0,0,0,0,2,11,48,192,140,28,6,1,0,0,0,0,0,0}
(1 row)
SELECT * FROM anser.stats_counters();
counter | value
----------------------------+-------
parts_submitted | 1284
parts_accepted | 1281
parts_rejected | 3
channels_timed_out | 2
consumers_delivered | 426
consumers_cancelled | 2
(6 rows)
```
Because `p50_ms` / `p99_ms` are derived from the fixed power-of-two buckets they
are approximate — bucket boundaries, not interpolated values. Say so in the
`README.md` metrics table rather than pretending to millisecond precision.
`total_ms` and `max_ms` are exact.
### Use case/motivation
_No response_
### Related issues
https://github.com/apache/cloudberry/pull/1942
### Are you willing to submit a PR?
- [ ] Yes I am willing to submit a PR!
GitHub link: https://github.com/apache/cloudberry/discussions/1958
----
This is an automatically sent email for dev@cloudberry.apache.org.
To unsubscribe, please send an email to: dev-unsubscribe@cloudberry.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cloudberry.apache.org
For additional commands, e-mail: dev-help@cloudberry.apache.org
Re: [D] [Ideas] Add instrumentation and latency metrics to the Anser subsystem [cloudberry]
Posted by "MisterRaindrop (via GitHub)" <gi...@apache.org>.
GitHub user MisterRaindrop added a comment to the discussion: [Ideas] Add instrumentation and latency metrics to the Anser subsystem
Hi, this looks interesting. I'd like to work on this.
I'm thinking of starting with **Change 1 — per-node wait time in EXPLAIN** as the first step, including the producer/consumer wait instrumentation and the segment-side extra text handling.
Is anyone already working on this part? If not, I'd be happy to take it and submit a PR for Change 1 first.
GitHub link: https://github.com/apache/cloudberry/discussions/1958#discussioncomment-18299830
----
This is an automatically sent email for dev@cloudberry.apache.org.
To unsubscribe, please send an email to: dev-unsubscribe@cloudberry.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cloudberry.apache.org
For additional commands, e-mail: dev-help@cloudberry.apache.org
Re: [D] [Ideas] Add instrumentation and latency metrics to the Anser subsystem [cloudberry]
Posted by "leborchuk (via GitHub)" <gi...@apache.org>.
GitHub user leborchuk edited a discussion: [Ideas] Add instrumentation and latency metrics to the Anser subsystem
# Description
Anser (`gpcontrib/anser/`) is a runtime pub/sub facility: producer nodes on the
segments publish a bloom filter over a join-build key, the coordinator unions
the parts, and consumer nodes on the segments receive it and prune probe rows.
Everything travels over the dispatch connection the coordinator already holds
open to each segment — there is no shared memory and no background worker. See
`gpcontrib/anser/README.md` for the architecture before starting.
Today we can see *what* the filter did (`Rows Removed by Bloom Filter` in
`EXPLAIN ANALYZE`) but nothing about *what it cost*. A consumer blocks until the
coordinator delivers the merged filter; if that wait is expensive the filter is
a net loss, and we currently have no way to tell from a plan.
We know the wait is not negligible. A traced exchange on a 3-segment demo
cluster with a 1 MB filter took **34 ms** end to end, and only ~13 ms of that
was work:
| t (ms) | Event |
| --- | --- |
| 0.0 | 3 producers build their filters |
| 8.7 – 10.0 | all 3 published (`sent=1`) |
| 10.2 | 3 consumers subscribe and block |
| 16.8 / 24.0 / 31.4 | coordinator folds part 1 / 2 / 3 |
| 31.4 | channel complete, delivering |
| 33.2 – 34.0 | all 3 consumers hold the filter |
The parts were *sent* within 1.3 ms of each other but *folded* ~7.2 ms apart —
so roughly **21 ms, 60% of the exchange, is the coordinator picking parts up one
at a time**, not doing work (a 1 MB fold is ~0.1 ms, a 1.4 MB base64 decode
~1–2 ms). That pickup latency is gated by the interconnect wait loop, it scales
with segment count, and nothing in `EXPLAIN` shows it. Attributing it is the
main reason this issue exists.
## Goal
Make every wait and every queueing delay in Anser visible in `EXPLAIN`, on both
sides of the exchange, so a filter that costs more than it saves can be
identified from a plan alone.
## Definition of done
- [ ] `EXPLAIN (ANALYZE, VERBOSE)` shows producer publish cost and consumer wait
time, **including for segment-executed nodes**.
- [ ] The coordinator's side is attributable: per-channel first-part arrival,
completion, delivery, and per-part fold time.
- [ ] A consumer that fails open says *why* — delivered, cancelled or timed out.
- [ ] Regression tests pass and contain no timing-dependent expected values.
- [ ] `README.md` gains a "Metrics" section: every field, its unit, and where it
is measured.
- [ ] No new allocation or locking on the data path; no per-tuple timing calls.
- [ ] Core (`src/`) is untouched.
## What to measure
Three vantage points, each with **its own clock**. Keeping them separate is the
single most important thing to get right — do not subtract a timestamp taken on
a segment from one taken on the coordinator.
| Vantage point | What it can measure | Where |
| --- | --- | --- |
| **Producer node** (segment) | build, serialize, base64 encode, send. There is **no wait**: publishing is fire-and-forget since the dispatch-transport migration | `AnserProducePublishPart()` (`src/anserbloomproduce.c:60`), `AnserSidebandPublish()` (`src/ansersideband.c:94`) |
| **Consumer node** (segment) | subscribe → payload in hand; how many messages it read while waiting; the outcome | `ExecAnserBloomFilterConsumeSideband()` (`src/anserbloomconsume.c:100`), `AnserSidebandConsumeWait()` (`src/ansersideband.c:137`) |
| **Coordinator** (QD backend) | first part arrival → complete → delivered, and fold time per part | `anser_disp_apply_part()` (`src/anserdispatch.c:302`), `anser_disp_deliver()` (`:372`), `anser_disp_push()` (`:394`) |
The pickup latency that dominates the trace above is *between* vantage points
(segment send → coordinator fold). Deriving it exactly needs a send timestamp on
the wire, which means comparable clocks — see "Optional: exact pickup latency".
Note this issue does **not** ask for cluster-wide counters or a
`anser.stats()` view. The subsystem has no shared memory any more, and it
creates no catalog objects (`CREATE EXTENSION` is not part of installing it), so
there is nowhere for cross-backend totals to live and no SQL surface to expose
them. Per-query numbers in `EXPLAIN` are the deliverable. If cross-query
aggregation is wanted later it needs its own design discussion — reintroducing
either shared memory or an extension is a bigger decision than instrumentation.
## Implementation
Three changes, in this order. Each is independently reviewable and testable.
### Change 1 — per-node numbers in EXPLAIN
- [ ] Time the publish in the producer node and the receive in the consumer
node. Record per node: **number of waits**, **total wait time**, **longest
single wait**, and for the consumer the **outcome**.
- Producer: wrap `AnserProducePublishPart()`; the accumulators belong in
`AnserBloomProduceScanState` (`src/anserplanexec.c:80`), and the publish
is triggered from `anser_produce_next()` (`:356`) when the child is
exhausted.
- Consumer: wrap `ExecAnserBloomFilterConsumeSideband()`; accumulators in
`AnserBloomConsumeScanState` (`src/anserplanexec.c:94`), driven from
`anser_consume_receive()` (`:498`).
- [ ] Print them from `anser_produce_explain()` (`src/anserplanexec.c:435`) and
`anser_consume_explain()` (`:648`), gated on `es->analyze && es->verbose`.
Use `ExplainPropertyInteger` / `ExplainPropertyFloat` so JSON/YAML/XML
output works for free — never `appendStringInfo` into the plan text.
**The trap you must handle.** A field you add to the node state on a *segment*
does **not** reach the QD. Read the comment at `src/anserplanexec.c` above the
`InstrCountFiltered1/2` calls in the consumer's exec loop: the existing code
uses those counters deliberately, because only the fixed fields of
`CdbExplain_StatInst` (`src/backend/commands/explain_gp.c:44`) travel back. Your
new timers are not in that struct.
The supported escape hatch is the per-node *extra text* channel, which is how
`Hash` reports `Extra Text: (seg2) Hash chain length ...`:
- `PlanState.cdbexplainbuf` and `PlanState.cdbexplainfun`
(`src/include/nodes/execnodes.h:1152-1153`)
- collected on the segment by `cdbexplain_collectExtraText()`
(`src/backend/commands/explain_gp.c:1308`) and shipped to the QD
- **copy the pattern from `src/backend/executor/nodeRuntimeFilter.c:174-177`** —
the closest existing analogue, a runtime-filter node doing exactly this
Allocate `cdbexplainbuf` in `*_begin` when `estate->es_instrument` is set,
install a `cdbexplainfun` that appends your numbers, and the QD shows them as
`Extra Text` per segment. **No core change is needed** — if you find yourself
editing anything under `src/`, stop and re-read this paragraph.
### Change 2 — the coordinator's side
The QD merges in the backend running the query, so its numbers can ride out on
the plan rather than into a stats table.
- [ ] Add per-channel timing to `AnserDispChannel` (`src/anserdispatch.c`):
first-part arrival, completion, delivery, accumulated fold time, and part
count. All from one clock, all in memory already owned by the query.
- [ ] Surface them on the *consumer* node's `EXPLAIN` output — the QD is where
that node's plan output is assembled, so no transport is needed. One line
of `key=value` pairs, matching the shape of the `Extra Text` lines.
- [ ] Use `instr_time` throughout (`src/include/portability/instr_time.h`:
`INSTR_TIME_SET_CURRENT`, `INSTR_TIME_SUBTRACT`,
`INSTR_TIME_GET_MICROSEC`). Do **not** use `GetCurrentTimestamp()` for
durations.
**Accuracy caveats to document in the code.** The consumer sleeps in slices
(`ANSER_SIDEBAND_POLL_MS` = 100 ms in `src/ansersideband.c`), so measure wall
time across the whole wait call, never by counting loop iterations, and note
that sub-poll-interval waits are quantized. On the coordinator side, note that
fold time and pickup latency are different things and the fold is the small one.
### Change 3 — build on the existing trace, don't duplicate it
`anser.debug` (`ANSER_DEBUG()`, `include/anser.h:78`) already logs every step of
the exchange with the sender's identity. Reuse its call sites rather than adding
a parallel set:
- [ ] Where a trace line already exists, extend it with the new measurement
instead of adding a second line.
- [ ] Keep the log format one line of `key=value` pairs — it is grep-and-awk
material and people already have scripts.
- [ ] The README's "Tracing an exchange" section documents the current output;
update it in the same commit.
### Optional: exact pickup latency
The 21 ms above can only be attributed exactly by comparing a segment's send
time with the coordinator's fold time. If you want that:
- [ ] Add a send timestamp to the QE→QD wire header (`anser1 ...` in
`include/ansersideband.h`) — there is room, and the parser takes fields
positionally, so bump `ANSER_WIRE_TAG` if you change the layout.
- [ ] Report it as a separate, clearly-labelled field and **document that it is
meaningless without synchronised clocks** across hosts. Do not fold it
into any other total.
If that is more than you want to take on, skip it: reporting each side's own
durations still narrows the gap to "time spent between publish and fold", which
is the actionable finding.
## Testing
- [ ] Extend `gpcontrib/anser/sql/anser_test.sql` (+ `expected/anser_test.out`).
- [ ] **Never put a measured time in expected output** — the tests would fail
randomly. Assert properties instead: a counter is `> 0`, a wait total
increased after a known round trip, an outcome field says `delivered`.
Return booleans from C test helpers (`src/anser_test.c`) rather than
printing numbers.
- [ ] For the `EXPLAIN` part, prefer asserting on plan *shape* — a raw
`EXPLAIN (ANALYZE, VERBOSE)` in expected output is unstable. If you must,
filter it through a query that only checks the property is present.
- [ ] Run: `make -C gpcontrib/anser install && make -C gpcontrib/anser installcheck`
(the `installcheck` target arms the cluster itself). Requires
`shared_preload_libraries='anser'` and `anser.enable=on`; no
`CREATE EXTENSION` is needed for the subsystem itself.
## What I expect from code
### `EXPLAIN (ANALYZE, VERBOSE)` — the normal case
Three segments, `anser_rf_build` (200 rows) joined to `anser_rf_probe`
(2000 rows), the filter working as intended:
```
Gather Motion 3:1 (slice1; segments: 3) (actual time=38.412..39.104 rows=200 loops=1)
Output: b.name, p.payload
-> Hash Join (actual time=35.881..36.402 rows=67 loops=1)
Output: b.name, p.payload
Hash Cond: (p.id = b.id)
-> Custom Scan (Anser Bloom Consumer) (actual time=31.902..33.114 rows=73 loops=1)
Output: p.id, p.payload
Bloom Filter Size: 1048576 bytes
Bloom Filter Stats: memory=1024kB checked=667 rejected=594
Rows Removed by Bloom Filter: 594
Anser Waits: 1
Anser Wait Time: 23.774 ms
Anser Max Wait: 23.774 ms
Anser Result: delivered
Anser Coordinator: parts=3 first=16.840ms complete=31.361ms delivered=31.389ms fold=0.31ms
Extra Text: (seg0) Anser consumer: waits=1 total=23.774ms max=23.774ms reads=1 result=delivered
-> Seq Scan on public.anser_rf_probe p (actual time=0.021..0.204 rows=667 loops=1)
Output: p.id, p.payload
-> Hash (actual time=2.510..2.511 rows=67 loops=1)
Output: b.name, b.id
Buckets: 262144 Batches: 1 Memory Usage: 2049kB
-> Redistribute Motion 3:3 (slice2; segments: 3) (actual time=1.884..2.301 rows=67 loops=1)
Output: b.name, b.id
Hash Key: b.id
-> Custom Scan (Anser Bloom Producer) (actual time=0.031..10.002 rows=67 loops=1)
Output: b.name, b.id
Bloom Filter Size: 1048576 bytes
Bloom Filter Stats: memory=1024kB
Anser Publish Time: 1.310 ms
Extra Text: (seg1) Anser producer: parts=1 bytes=1048592 encode=1.021ms send=0.289ms
-> Seq Scan on public.anser_rf_build b (actual time=0.014..0.098 rows=67 loops=1)
Output: b.name, b.id
Optimizer: Postgres query optimizer
Execution Time: 39.884 ms
```
Read this carefully — it encodes several requirements:
- **The producer has no wait, only a cost.** It publishes fire-and-forget, so
report `Anser Publish Time` (encode + send), not a wait count. Anything
labelled "wait" on the producer is a leftover from the old libpq transport,
where it blocked for an acknowledgement.
- **`Anser Coordinator`** is the line that makes the trace above legible:
`first`/`complete`/`delivered` are offsets on the QD clock, `fold` is real
work. In this example `complete - first = 14.5ms` for `fold=0.31ms`, which
says the cost is pickup, not merging.
- **`Anser Result`** must distinguish `delivered` / `cancelled` / `timeout`.
Without it, a fast failure and a successful delivery look identical.
- **`reads=` on the consumer** — messages taken off the socket while waiting.
`reads=0` on a timeout means nothing ever arrived; a non-zero count means
something arrived that was not ours, which is a different bug.
- **The `Extra Text` line is the per-segment breakdown** shipped through
`cdbexplainbuf`. The summary properties above it are the winning segment's
values, like every other per-node MPP statistic. One line, `key=value`, no
wrapping.
- **Where the time lands is not symmetric.** The producer publishes after its
child is exhausted, so its cost shows in the node's *last* tuple time
(`0.031..10.002`). The consumer must receive before returning anything, so its
wait shows in the *first* tuple time (`31.902..`). Do not "fix" this; it is
the truth about when each side blocks.
- The consumer emits 73 rows but the join emits 67: those 6 are bloom false
positives. The filter may pass rows that do not join — it must never reject
one that does.
### `EXPLAIN (ANALYZE)` without VERBOSE — unchanged
The new lines are VERBOSE-only. Plain `ANALYZE` keeps exactly today's output:
```
-> Custom Scan (Anser Bloom Consumer) (actual time=31.902..33.114 rows=73 loops=1)
Bloom Filter Size: 1048576 bytes
Bloom Filter Stats: memory=1024kB checked=667 rejected=594
Rows Removed by Bloom Filter: 594
```
### `EXPLAIN (ANALYZE, VERBOSE)` — the case this feature exists for
A producer never published (squelched, or a segment whose slice was abandoned),
so the channel never completed and the consumer waited `anser.timeout_ms` for
nothing before failing open. The query is still correct — just slower than with
the feature off, which is precisely what we cannot see today:
```
-> Custom Scan (Anser Bloom Consumer) (actual time=1002.774..1003.918 rows=667 loops=1)
Output: p.id, p.payload
Bloom Filter Size: 1048576 bytes
Bloom Filter Stats: memory=1024kB (no filter received)
Anser Waits: 1
Anser Wait Time: 1000.118 ms
Anser Max Wait: 1000.118 ms
Anser Result: timeout
Anser Coordinator: parts=2 first=8.204ms complete=- delivered=- fold=0.21ms
Extra Text: (seg2) Anser consumer: waits=1 total=1000.118ms max=1000.118ms reads=0 result=timeout
```
`rows=667` — every probe row passed, no pruning happened, and a second was spent
waiting. Note `parts=2` with no completion: the coordinator's line shows exactly
*why* it timed out, which is the diagnosis this whole issue is for.
### Use case/motivation
_No response_
### Related issues
https://github.com/apache/cloudberry/pull/1942
### Are you willing to submit a PR?
- [ ] Yes I am willing to submit a PR!
GitHub link: https://github.com/apache/cloudberry/discussions/1958
----
This is an automatically sent email for dev@cloudberry.apache.org.
To unsubscribe, please send an email to: dev-unsubscribe@cloudberry.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cloudberry.apache.org
For additional commands, e-mail: dev-help@cloudberry.apache.org
Re: [D] [Ideas] Add instrumentation and latency metrics to the Anser subsystem [cloudberry]
Posted by "TheBuilderJR (via GitHub)" <gi...@apache.org>.
GitHub user TheBuilderJR added a comment to the discussion: [Ideas] Add instrumentation and latency metrics to the Anser subsystem
For the `anser.stats()` / `stats_reset()` contract, could each snapshot identify its reset generation, and could the API document how a reader knows a reset has completed? A consumer computing interval rates from cumulative counters needs to distinguish two reads that straddle a reset. Checking for a negative delta alone can miss the reset if enough new activity has already exceeded the previous count.
This also affects interval histogram quantiles: subtract corresponding bucket counts only across compatible snapshots from one reset generation, then derive an approximate quantile from that interval distribution; subtracting the displayed p99 values would not give an interval p99. Given the no-new-locks constraint, stating whether count, total time and bucket reads are a best-effort snapshot would help consumers avoid asserting exact consistency during concurrent updates.
This is feedback on the proposed API, not a reproduced implementation issue. Disclosure: I build Telemetry; this reply was drafted with AI assistance.
GitHub link: https://github.com/apache/cloudberry/discussions/1958#discussioncomment-18319661
----
This is an automatically sent email for dev@cloudberry.apache.org.
To unsubscribe, please send an email to: dev-unsubscribe@cloudberry.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cloudberry.apache.org
For additional commands, e-mail: dev-help@cloudberry.apache.org
Re: [D] [Ideas] Add instrumentation and latency metrics to the Anser subsystem [cloudberry]
Posted by "Alena0704 (via GitHub)" <gi...@apache.org>.
GitHub user Alena0704 added a comment to the discussion: [Ideas] Add instrumentation and latency metrics to the Anser subsystem
I've been working on something close to Change 1, but from the executor side: per-node wait timing for cross-slice blocking.
My original motivation was a bit different from performance analysis — I wanted a way to catch queries that get stuck (or fail outright) because of a cross-slice bug, where the optimizer and the executor disagree about slice assignment and producer/consumer locality is broken. That was the subject of my talk at Community Over Code Asia, "When the Optimizer Lies: Debugging Cross-Slice Execution in Apache Cloudberry": a Shared Scan over a CTE on a replicated table, hidden behind a scalar SubPlan, ends up hanging or failing with temporary file errors, and from the outside there is nothing to look at. Latency instrumentation turned out to be the practical way to make those cases visible — a consumer waiting forever on a producer that will never publish looks exactly like an unbounded wait on one node.
So I implemented it in the core as per-node wait statistics. In open-gpdb I added wait stats for cross-slice ShareInputScan (open-gpdb/gpdb#405): the consumer side measures how long it blocks waiting for the producer slice, and the elapsed time is reported in three ways — EXPLAIN ANALYZE (Cross-slice wait: N ms max (segK), M ms avg x P workers), the stats collector (cross_slice_wait_ms as a per-query aggregate), and the error context when a query is cancelled while blocked (e.g. by statement_timeout), which is what makes the pathological cases traceable after the fact. Only waits of 1 ms and above are counted, so there are no per-tuple timing calls — which matches the constraint listed in the DoD here.
It also makes wait skew across segments visible: the max/avg split per worker shows whether one segment is holding everything up or the wait is uniform.
The mechanism is generic enough that the same shape (per-node accumulator → max/avg per segment → EXPLAIN VERBOSE + a query-level aggregate) should fit the Anser producer/consumer waits directly. If the community is interested, I'd be happy to port it to Cloudberry — either as a general per-node wait-timing facility that Change 1 can build on, or just as input for whoever picks up Change 1.
GitHub link: https://github.com/apache/cloudberry/discussions/1958#discussioncomment-18302309
----
This is an automatically sent email for dev@cloudberry.apache.org.
To unsubscribe, please send an email to: dev-unsubscribe@cloudberry.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cloudberry.apache.org
For additional commands, e-mail: dev-help@cloudberry.apache.org
Re: [D] [Ideas] Add instrumentation and latency metrics to the Anser subsystem [cloudberry]
Posted by "leborchuk (via GitHub)" <gi...@apache.org>.
GitHub user leborchuk added a comment to the discussion: [Ideas] Add instrumentation and latency metrics to the Anser subsystem
> Hi, this looks interesting. I'd like to work on this.
>
> I'm thinking of starting with **Change 1 — per-node wait time in EXPLAIN** as the first step, including the producer/consumer wait instrumentation and the segment-side extra text handling.
>
> Is anyone already working on this part? If not, I'd be happy to take it and submit a PR for Change 1 first.
Thank you! I've updated description to reflect actual changes in a code. In #1942 we found out that runtime data could be sent in existing QD<->QE session, that's awesome, save us a lot of CPU/time ) Why I created issue while original PR wasn't merged - because I'm in context right now фтв have all the necessary information at hand.
GitHub link: https://github.com/apache/cloudberry/discussions/1958#discussioncomment-18333333
----
This is an automatically sent email for dev@cloudberry.apache.org.
To unsubscribe, please send an email to: dev-unsubscribe@cloudberry.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cloudberry.apache.org
For additional commands, e-mail: dev-help@cloudberry.apache.org
Re: [D] [Ideas] Add instrumentation and latency metrics to the Anser subsystem [cloudberry]
Posted by "Alena0704 (via GitHub)" <gi...@apache.org>.
GitHub user Alena0704 edited a comment on the discussion: [Ideas] Add instrumentation and latency metrics to the Anser subsystem
I've been working on something close to Change 1 (since July), but from the executor side: per-node wait timing for cross-slice blocking.
My original motivation was a bit different from performance analysis — I wanted a way to catch queries that get stuck (or fail outright) because of a cross-slice bug, where the optimizer and the executor disagree about slice assignment and producer/consumer locality is broken. That was the subject of my talk at Community Over Code Asia, "When the Optimizer Lies: Debugging Cross-Slice Execution in Apache Cloudberry": a Shared Scan over a CTE on a replicated table, hidden behind a scalar SubPlan, ends up hanging or failing with temporary file errors, and from the outside there is nothing to look at. Latency instrumentation turned out to be the practical way to make those cases visible — a consumer waiting forever on a producer that will never publish looks exactly like an unbounded wait on one node.
So I implemented it in the core as per-node wait statistics. In open-gpdb I added wait stats for cross-slice ShareInputScan (open-gpdb/gpdb#405): the consumer side measures how long it blocks waiting for the producer slice, and the elapsed time is reported in three ways — EXPLAIN ANALYZE (Cross-slice wait: N ms max (segK), M ms avg x P workers), the stats collector (cross_slice_wait_ms as a per-query aggregate), and the error context when a query is cancelled while blocked (e.g. by statement_timeout), which is what makes the pathological cases traceable after the fact.
It also makes wait skew across segments visible: the max/avg split per worker shows whether one segment is holding everything up or the wait is uniform.
The mechanism is generic enough that the same shape (per-node accumulator → max/avg per segment → EXPLAIN VERBOSE + a query-level aggregate) should fit the Anser producer/consumer waits directly. If the community is interested, I'd be happy to port it to Cloudberry — either as a general per-node wait-timing facility that Change 1 can build on, or just as input for whoever picks up Change 1.
GitHub link: https://github.com/apache/cloudberry/discussions/1958#discussioncomment-18302309
----
This is an automatically sent email for dev@cloudberry.apache.org.
To unsubscribe, please send an email to: dev-unsubscribe@cloudberry.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cloudberry.apache.org
For additional commands, e-mail: dev-help@cloudberry.apache.org
Re: [D] [Ideas] Add instrumentation and latency metrics to the Anser subsystem [cloudberry]
Posted by "leborchuk (via GitHub)" <gi...@apache.org>.
GitHub user leborchuk added a comment to the discussion: [Ideas] Add instrumentation and latency metrics to the Anser subsystem
> I've been working on something close to Change 1 (since July), but from the executor side: per-node wait timing for cross-slice blocking.
>
> My original motivation was a bit different from performance analysis — I wanted a way to catch queries that get stuck (or fail outright) because of a cross-slice bug, where the optimizer and the executor disagree about slice assignment and producer/consumer locality is broken. That was the subject of my talk at Community Over Code Asia, "When the Optimizer Lies: Debugging Cross-Slice Execution in Apache Cloudberry": a Shared Scan over a CTE on a replicated table, hidden behind a scalar SubPlan, ends up hanging or failing with temporary file errors, and from the outside there is nothing to look at. Latency instrumentation turned out to be the practical way to make those cases visible — a consumer waiting forever on a producer that will never publish looks exactly like an unbounded wait on one node.
>
> So I implemented it in the core as per-node wait statistics. In open-gpdb I added wait stats for cross-slice ShareInputScan ([open-gpdb/gpdb#405](https://github.com/open-gpdb/gpdb/pull/405)): the consumer side measures how long it blocks waiting for the producer slice, and the elapsed time is reported in three ways — EXPLAIN ANALYZE (Cross-slice wait: N ms max (segK), M ms avg x P workers), the stats collector (cross_slice_wait_ms as a per-query aggregate), and the error context when a query is cancelled while blocked (e.g. by statement_timeout), which is what makes the pathological cases traceable after the fact.
>
> It also makes wait skew across segments visible: the max/avg split per worker shows whether one segment is holding everything up or the wait is uniform.
>
> The mechanism is generic enough that the same shape (per-node accumulator → max/avg per segment → EXPLAIN VERBOSE + a query-level aggregate) should fit the Anser producer/consumer waits directly. If the community is interested, I'd be happy to port it to Cloudberry — either as a general per-node wait-timing facility that Change 1 can build on, or just as input for whoever picks up Change 1. I can prepare pull request to cloudberry if the community is interested in it.
Thank you, it will be quite usefull. I do not think it should be part of Anser - it's more general data, needed to DBA regardless of whether Anser is enabled or not. You should definitely finish your work and let collect this statistics.
GitHub link: https://github.com/apache/cloudberry/discussions/1958#discussioncomment-18333382
----
This is an automatically sent email for dev@cloudberry.apache.org.
To unsubscribe, please send an email to: dev-unsubscribe@cloudberry.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cloudberry.apache.org
For additional commands, e-mail: dev-help@cloudberry.apache.org
Re: [D] [Ideas] Add instrumentation and latency metrics to the Anser subsystem [cloudberry]
Posted by "leborchuk (via GitHub)" <gi...@apache.org>.
GitHub user leborchuk added a comment to the discussion: [Ideas] Add instrumentation and latency metrics to the Anser subsystem
> For the `anser.stats()` / `stats_reset()` contract, could each snapshot identify its reset generation, and could the API document how a reader knows a reset has completed? A consumer computing interval rates from cumulative counters needs to distinguish two reads that straddle a reset. Checking for a negative delta alone can miss the reset if enough new activity has already exceeded the previous count.
>
> This also affects interval histogram quantiles: subtract corresponding bucket counts only across compatible snapshots from one reset generation, then derive an approximate quantile from that interval distribution; subtracting the displayed p99 values would not give an interval p99. Given the no-new-locks constraint, stating whether count, total time and bucket reads are a best-effort snapshot would help consumers avoid asserting exact consistency during concurrent updates.
>
> This is feedback on the proposed API, not a reproduced implementation issue. Disclosure: I build Telemetry; this reply was drafted with AI assistance.
Yes, thank you. It is quite important. If we want to add a stat() method, there should be a `stats_reset()' method and the time when the reset was performed. I remember a multi-year discussion among pg-hackers about adding a reset time to pg_stat_statements. Luckily, it finally got merged )
GitHub link: https://github.com/apache/cloudberry/discussions/1958#discussioncomment-18333486
----
This is an automatically sent email for dev@cloudberry.apache.org.
To unsubscribe, please send an email to: dev-unsubscribe@cloudberry.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cloudberry.apache.org
For additional commands, e-mail: dev-help@cloudberry.apache.org
Re: [D] [Ideas] Add instrumentation and latency metrics to the Anser subsystem [cloudberry]
Posted by "Alena0704 (via GitHub)" <gi...@apache.org>.
GitHub user Alena0704 edited a comment on the discussion: [Ideas] Add instrumentation and latency metrics to the Anser subsystem
I've been working on something close to Change 1 (since July), but from the executor side: per-node wait timing for cross-slice blocking.
My original motivation was a bit different from performance analysis — I wanted a way to catch queries that get stuck (or fail outright) because of a cross-slice bug, where the optimizer and the executor disagree about slice assignment and producer/consumer locality is broken. That was the subject of my talk at Community Over Code Asia, "When the Optimizer Lies: Debugging Cross-Slice Execution in Apache Cloudberry": a Shared Scan over a CTE on a replicated table, hidden behind a scalar SubPlan, ends up hanging or failing with temporary file errors, and from the outside there is nothing to look at. Latency instrumentation turned out to be the practical way to make those cases visible — a consumer waiting forever on a producer that will never publish looks exactly like an unbounded wait on one node.
So I implemented it in the core as per-node wait statistics. In open-gpdb I added wait stats for cross-slice ShareInputScan (open-gpdb/gpdb#405): the consumer side measures how long it blocks waiting for the producer slice, and the elapsed time is reported in three ways — EXPLAIN ANALYZE (Cross-slice wait: N ms max (segK), M ms avg x P workers), the stats collector (cross_slice_wait_ms as a per-query aggregate), and the error context when a query is cancelled while blocked (e.g. by statement_timeout), which is what makes the pathological cases traceable after the fact.
It also makes wait skew across segments visible: the max/avg split per worker shows whether one segment is holding everything up or the wait is uniform.
The mechanism is generic enough that the same shape (per-node accumulator → max/avg per segment → EXPLAIN VERBOSE + a query-level aggregate) should fit the Anser producer/consumer waits directly. If the community is interested, I'd be happy to port it to Cloudberry — either as a general per-node wait-timing facility that Change 1 can build on, or just as input for whoever picks up Change 1. I can prepare pull request to cloudberry if the community is interested in it.
GitHub link: https://github.com/apache/cloudberry/discussions/1958#discussioncomment-18302309
----
This is an automatically sent email for dev@cloudberry.apache.org.
To unsubscribe, please send an email to: dev-unsubscribe@cloudberry.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cloudberry.apache.org
For additional commands, e-mail: dev-help@cloudberry.apache.org
Re: [D] [Ideas] Add instrumentation and latency metrics to the Anser subsystem [cloudberry]
Posted by "Alena0704 (via GitHub)" <gi...@apache.org>.
GitHub user Alena0704 edited a comment on the discussion: [Ideas] Add instrumentation and latency metrics to the Anser subsystem
I've been working on something close to Change 1, but from the executor side: per-node wait timing for cross-slice blocking.
My original motivation was a bit different from performance analysis — I wanted a way to catch queries that get stuck (or fail outright) because of a cross-slice bug, where the optimizer and the executor disagree about slice assignment and producer/consumer locality is broken. That was the subject of my talk at Community Over Code Asia, "When the Optimizer Lies: Debugging Cross-Slice Execution in Apache Cloudberry": a Shared Scan over a CTE on a replicated table, hidden behind a scalar SubPlan, ends up hanging or failing with temporary file errors, and from the outside there is nothing to look at. Latency instrumentation turned out to be the practical way to make those cases visible — a consumer waiting forever on a producer that will never publish looks exactly like an unbounded wait on one node.
So I implemented it in the core as per-node wait statistics. In open-gpdb I added wait stats for cross-slice ShareInputScan (open-gpdb/gpdb#405): the consumer side measures how long it blocks waiting for the producer slice, and the elapsed time is reported in three ways — EXPLAIN ANALYZE (Cross-slice wait: N ms max (segK), M ms avg x P workers), the stats collector (cross_slice_wait_ms as a per-query aggregate), and the error context when a query is cancelled while blocked (e.g. by statement_timeout), which is what makes the pathological cases traceable after the fact.
It also makes wait skew across segments visible: the max/avg split per worker shows whether one segment is holding everything up or the wait is uniform.
The mechanism is generic enough that the same shape (per-node accumulator → max/avg per segment → EXPLAIN VERBOSE + a query-level aggregate) should fit the Anser producer/consumer waits directly. If the community is interested, I'd be happy to port it to Cloudberry — either as a general per-node wait-timing facility that Change 1 can build on, or just as input for whoever picks up Change 1.
GitHub link: https://github.com/apache/cloudberry/discussions/1958#discussioncomment-18302309
----
This is an automatically sent email for dev@cloudberry.apache.org.
To unsubscribe, please send an email to: dev-unsubscribe@cloudberry.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cloudberry.apache.org
For additional commands, e-mail: dev-help@cloudberry.apache.org
Re: [D] [Ideas] Add instrumentation and latency metrics to the Anser subsystem [cloudberry]
Posted by "leborchuk (via GitHub)" <gi...@apache.org>.
GitHub user leborchuk added a comment to the discussion: [Ideas] Add instrumentation and latency metrics to the Anser subsystem
The examples of data on my dev demo cluster
1. How to trace - `set anser.debug=on;`
2. Example of raw data from logs
```
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.527686 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: producer init cond=0 part=0/1 elems=3334 payload=67108928 state=ok",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.551469 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD part cond=0 from seg2 (says part 2 of 3) 1/3 bytes=1048592 -> collecting",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.558633 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD part cond=0 from seg0 (says part 0 of 3) 2/3 bytes=1048592 -> collecting",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.558684 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD subscribe cond=0 from seg0 (channel still collecting)",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.558712 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD subscribe cond=0 from seg1 (channel still collecting)",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.558737 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD subscribe cond=0 from seg2 (channel still collecting)",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.565990 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD part cond=0 from seg1 (says part 1 of 3) 3/3 bytes=1048592 -> complete",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.566018 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD delivering cond=0 to 3 subscriber(s)",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.566477 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD pushed cond=0 bytes=1048592 cancelled=0",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.566860 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD pushed cond=0 bytes=1048592 cancelled=0",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.567277 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD pushed cond=0 bytes=1048592 cancelled=0",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast1/demoDataDir0/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.534745 UTC,"xifos","postgres",p88524,th1725312576,"127.0.0.1","56156",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg0,slice2,,,sx1,"LOG","00000","anser: producer init cond=0 part=0/3 elems=3334 payload=67108928 state=ok",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast1/demoDataDir0/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.536508 UTC,"xifos","postgres",p88524,th1725312576,"127.0.0.1","56156",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg0,slice2,,,sx1,"LOG","00000","anser: producer child exhausted, publishing (state=ok)",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast1/demoDataDir0/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.543574 UTC,"xifos","postgres",p88524,th1725312576,"127.0.0.1","56156",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg0,slice2,,,sx1,"LOG","00000","anser: seg0 published cond=0 part=0/3 bytes=1048592 cancelled=0 sent=1",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast1/demoDataDir0/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.544858 UTC,"xifos","postgres",p88378,th1725312576,"127.0.0.1","59664",2026-09-07 11:26:40 UTC,0,con23,cmd6,seg0,slice1,,,sx1,"LOG","00000","anser: seg0 subscribed cond=0, waiting up to 1000 ms",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast1/demoDataDir0/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.567852 UTC,"xifos","postgres",p88378,th1725312576,"127.0.0.1","59664",2026-09-07 11:26:40 UTC,0,con23,cmd6,seg0,slice1,,,sx1,"LOG","00000","anser: seg0 received cond=0 bytes=1048592 cancelled=0",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast2/demoDataDir1/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.534632 UTC,"xifos","postgres",p88525,th867016256,"127.0.0.1","33560",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg1,slice2,,,sx1,"LOG","00000","anser: producer init cond=0 part=1/3 elems=3334 payload=67108928 state=ok",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast2/demoDataDir1/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.538237 UTC,"xifos","postgres",p88525,th867016256,"127.0.0.1","33560",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg1,slice2,,,sx1,"LOG","00000","anser: producer child exhausted, publishing (state=ok)",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast2/demoDataDir1/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.544624 UTC,"xifos","postgres",p88525,th867016256,"127.0.0.1","33560",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg1,slice2,,,sx1,"LOG","00000","anser: seg1 published cond=0 part=1/3 bytes=1048592 cancelled=0 sent=1",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast2/demoDataDir1/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.544876 UTC,"xifos","postgres",p88380,th867016256,"127.0.0.1","55068",2026-09-07 11:26:40 UTC,0,con23,cmd6,seg1,slice1,,,sx1,"LOG","00000","anser: seg1 subscribed cond=0, waiting up to 1000 ms",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast2/demoDataDir1/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.568240 UTC,"xifos","postgres",p88380,th867016256,"127.0.0.1","55068",2026-09-07 11:26:40 UTC,0,con23,cmd6,seg1,slice1,,,sx1,"LOG","00000","anser: seg1 received cond=0 bytes=1048592 cancelled=0",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast3/demoDataDir2/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.534629 UTC,"xifos","postgres",p88526,th72871488,"127.0.0.1","47130",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg2,slice2,,,sx1,"LOG","00000","anser: producer init cond=0 part=2/3 elems=3334 payload=67108928 state=ok",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast3/demoDataDir2/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.536992 UTC,"xifos","postgres",p88526,th72871488,"127.0.0.1","47130",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg2,slice2,,,sx1,"LOG","00000","anser: producer child exhausted, publishing (state=ok)",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast3/demoDataDir2/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.543316 UTC,"xifos","postgres",p88526,th72871488,"127.0.0.1","47130",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg2,slice2,,,sx1,"LOG","00000","anser: seg2 published cond=0 part=2/3 bytes=1048592 cancelled=0 sent=1",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast3/demoDataDir2/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.544872 UTC,"xifos","postgres",p88379,th72871488,"127.0.0.1","46024",2026-09-07 11:26:40 UTC,0,con23,cmd6,seg2,slice1,,,sx1,"LOG","00000","anser: seg2 subscribed cond=0, waiting up to 1000 ms",,,,,,"explain analyze select
/home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast3/demoDataDir2/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.568601 UTC,"xifos","postgres",p88379,th72871488,"127.0.0.1","46024",2026-09-07 11:26:40 UTC,0,con23,cmd6,seg2,slice1,,,sx1,"LOG","00000","anser: seg2 received cond=0 bytes=1048592 cancelled=0",,,,,,"explain analyze select
```
3. The conslusion based on debug data
Three-way events show the spread across segments:
```
┌─────────────┬────────────────────────────────────────────────────┐
│ t (ms) │ Event │
├─────────────┼────────────────────────────────────────────────────┤
│ 0.0 │ 3 producers init — part=0/3, 1/3, 2/3 (spread 0.1) │
├─────────────┼────────────────────────────────────────────────────┤
│ 1.9 – 3.6 │ children exhausted, publishing (seg0, seg2, seg1) │
├─────────────┼────────────────────────────────────────────────────┤
│ 8.7 – 10.0 │ all 3 published, sent=1 (seg2, seg0, seg1) │
├─────────────┼────────────────────────────────────────────────────┤
│ 10.2 – 10.2 │ 3 consumers subscribe (spread 0.02) │
├─────────────┼────────────────────────────────────────────────────┤
│ 16.8 │ QD folds seg2 → 1/3 collecting │
├─────────────┼────────────────────────────────────────────────────┤
│ 24.0 │ QD folds seg0 → 2/3 collecting │
├─────────────┼────────────────────────────────────────────────────┤
│ 24.1 │ QD receives the 3 subscribes (spread 0.05) │
├─────────────┼────────────────────────────────────────────────────┤
│ 31.4 │ QD folds seg1 → 3/3 complete │
├─────────────┼────────────────────────────────────────────────────┤
│ 31.4 │ QD delivering to 3 subscribers │
├─────────────┼────────────────────────────────────────────────────┤
│ 31.8 – 32.6 │ 3 pushes, 1048592 bytes each │
├─────────────┼────────────────────────────────────────────────────┤
│ 33.2 – 34.0 │ all 3 consumers received │
└─────────────┴────────────────────────────────────────────────────┘
```
34.0 ms first-init to last-received; 25.3 ms publish to received.
One thing that jumps out now that it's relative: the three parts were sent within 1.3 ms of each other (8.7 → 10.0) but folded 16.8 → 31.4, evenly spaced about 7.2 ms apart. So roughly 21 ms of the 34 is the coordinator picking parts up one at a time, not doing work — a 1 MB fold is ~0.1 ms and a 1.4 MB base64 decode ~1–2 ms. That points at the drain cadence: one part per processResults sweep, gated by the interconnect wait loop rather than by anything Anser does.
What I want - could gather the similar info without enabling debug mode and processing raw debug info
GitHub link: https://github.com/apache/cloudberry/discussions/1958#discussioncomment-18333241
----
This is an automatically sent email for dev@cloudberry.apache.org.
To unsubscribe, please send an email to: dev-unsubscribe@cloudberry.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@cloudberry.apache.org
For additional commands, e-mail: dev-help@cloudberry.apache.org