Skip to content

Add wait stats - #405

Draft
Alena0704 wants to merge 2 commits into
OPENGPDB_STABLEfrom
add-wait-stats
Draft

Add wait stats#405
Alena0704 wants to merge 2 commits into
OPENGPDB_STABLEfrom
add-wait-stats

Conversation

@Alena0704

Copy link
Copy Markdown
Contributor

Report cross-slice ShareInputScan wait

A ShareInputScan consumer placed in a slice other than its producer blocks
until the producer publishes the shared tuplestore. The wait is charged to
the node's own time, so an idle node looks slow, and a query killed by
statement_timeout while blocked leaves no trace at all.

Measure the wait on the consumer side and report it in three ways:

  • EXPLAIN ANALYZE prints "Cross-slice wait: N ms max (segK), M ms avg x P
    workers" under the node, for waits of 1 ms and above. Max against average
    shows whether one segment waited or all of them did.
  • An errcontext callback attaches the elapsed wait to any error raised while
    blocked, which covers the statement_timeout cancellation.
  • EState.es_cross_slice_wait holds the longest wait per query, and
    gp_stats_collector reports it as cross_slice_wait_ms.

Tests are added to src/test/regress/sql/shared_scan.sql for the planner and
the optimizer. The producer sleeps to force a wait above the threshold, and
a plpgsql wrapper checks only that the line is present, so no timing value
reaches the expected output. The metric is documented in
gpcontrib/gp_stats_collector/metric.md.

To reproduce:

create table sisw_foo (a int, b int) distributed by (a);
create table sisw_bar (c int, d int) distributed by (c);
insert into sisw_foo values (1, 2);
insert into sisw_bar select i, i from generate_series(1, 100) i;
analyze sisw_foo;
analyze sisw_bar;

set optimizer = off;
set gp_cte_sharing = on;

explain (analyze, costs off)
with cte as (select a, b, pg_sleep(0.5)::text as s from sisw_foo)
select x.a from cte x
union all
select y.a from cte y join sisw_bar on y.b = sisw_bar.c;

Only the segment holding the row sleeps, so its consumer blocks for half a
second while the others do not:

->  Shared Scan (share slice:id 2:0) (actual rows=1 loops=1)
      Cross-slice wait: 502.311 ms max (seg1), 0.240 ms avg x 2 workers.

Without the patch the node reports only its actual time, with the half
second charged to the scan itself.

A cross-slice ShareInputScan consumer blocks waiting for the producer
slice to publish its tuplestore. That wait is invisible: in EXPLAIN
ANALYZE the node just looks slow, and a query killed by statement_timeout
leaves no trace at all.

Measure the wait and surface it per segment in EXPLAIN ANALYZE (max, the
segment that waited longest, and the average). The max-vs-avg gap exposes
slice-to-slice wait skew, so the metric is useful for spotting anomalies,
not only for diagnosing a mis-wired cross-slice share. Only waits above
1 ms are shown, so plans of queries that do not wait are unchanged. An
errcontext callback attaches the elapsed wait to any error raised while
blocked -- most importantly the statement_timeout cancellation, the only
channel that survives a killed query. The wait is also rolled up per
query in EState.es_cross_slice_wait for the stats collector to report.
Add cross_slice_wait_ms to the collector's MetricInstrumentation and fill
it from EState.es_cross_slice_wait (the per-query cross-slice
ShareInputScan wait rolled up in the executor), reported in milliseconds.

A cross-slice ShareInputScan consumer blocks until its producer slice
publishes the shared tuplestore. Beyond catching a share wired between
slices that cannot reach each other, the wait is a general slice-to-slice
signal: yagpcc takes the max across segments, and a wide gap against the
average means the producer finished unevenly rather than the consumer
being slow. It also rises when the producer slice is starved of CPU or
interconnect, and it is the only trace left by a query killed on
statement_timeout while blocked there.

Filled outside the instrumentation block, since the executor measures the
wait whether or not instrumentation is on, and the statement_timeout case
often runs without it. A zero wait is not reported, so queries that never
waited get no empty instrumentation submessage.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant