From 865eda512e31b6a43b51a4e318d620b7b52e0dae Mon Sep 17 00:00:00 2001 From: Alena Rybakina Date: Sun, 26 Jul 2026 23:50:57 +0300 Subject: [PATCH 1/2] executor: account and report cross-slice ShareInputScan wait 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. --- src/backend/commands/explain_gp.c | 67 +++++++++++ src/backend/executor/nodeShareInputScan.c | 104 +++++++++++++++++- src/include/nodes/execnodes.h | 25 ++++- src/test/regress/expected/shared_scan.out | 39 +++++++ .../expected/shared_scan_optimizer.out | 39 +++++++ src/test/regress/sql/shared_scan.sql | 34 ++++++ 6 files changed, 303 insertions(+), 5 deletions(-) diff --git a/src/backend/commands/explain_gp.c b/src/backend/commands/explain_gp.c index 13218134471..091790e2e4c 100644 --- a/src/backend/commands/explain_gp.c +++ b/src/backend/commands/explain_gp.c @@ -112,6 +112,8 @@ typedef struct CdbExplain_StatInst ExplainSortMethod sortMethod; /* Type of sort */ ExplainSortSpaceType sortSpaceType; /* Sort space type */ long sortSpaceUsed; /* Memory / Disk used by sort(KBytes) */ + double shareinputwait; /* ShareInputScan: seconds blocked on another + * slice */ int bnotes; /* Offset to beginning of node's extra text */ int enotes; /* Offset to end of node's extra text */ } CdbExplain_StatInst; @@ -182,6 +184,14 @@ typedef struct CdbExplain_NodeSummary /* Summary of space used by sort */ CdbExplain_Agg sortSpaceUsed[NUM_SORT_SPACE_TYPE][NUM_SORT_METHOD]; + /* + * Time a cross-slice ShareInputScan spent blocked on another slice. + * Aggregated across workers, because the per-worker extra message text is + * selected by memory/row-count criteria and would otherwise report an + * arbitrary worker's wait rather than the worst one. + */ + CdbExplain_Agg shareinputwait; + /* insts array info */ int segindex0; /* segment id of insts[0] */ int ninst; /* num of StatInst entries in inst array */ @@ -995,6 +1005,14 @@ cdbexplain_collectStatsFromNode(PlanState *planstate, CdbExplain_SendStatCtx *ct si->sortMethod = String2ExplainSortMethod(instr->sortMethod); si->sortSpaceType = String2ExplainSortSpaceType(instr->sortSpaceType, si->sortMethod); si->sortSpaceUsed = instr->sortSpaceUsed; + + if (IsA(planstate, ShareInputScanState)) + { + ShareInputScanState *sisstate = (ShareInputScanState *) planstate; + + si->shareinputwait = + INSTR_TIME_GET_DOUBLE(sisstate->waitready_time); + } } /* cdbexplain_collectStatsFromNode */ @@ -1121,6 +1139,7 @@ cdbexplain_depositStatsToNode(PlanState *planstate, CdbExplain_RecvStatCtx *ctx) CdbExplain_DepStatAcc memory_accounting_global_peak; CdbExplain_DepStatAcc peakMemBalance; CdbExplain_DepStatAcc totalPartTableScanned; + CdbExplain_DepStatAcc shareinputwait; CdbExplain_DepStatAcc sortSpaceUsed[NUM_SORT_SPACE_TYPE][NUM_SORT_METHOD]; int imsgptr; int nInst; @@ -1146,6 +1165,7 @@ cdbexplain_depositStatsToNode(PlanState *planstate, CdbExplain_RecvStatCtx *ctx) cdbexplain_depStatAcc_init0(&totalWorkfileCreated); cdbexplain_depStatAcc_init0(&peakMemBalance); cdbexplain_depStatAcc_init0(&totalPartTableScanned); + cdbexplain_depStatAcc_init0(&shareinputwait); for (int idx = 0; idx < NUM_SORT_METHOD; ++idx) { cdbexplain_depStatAcc_init0(&sortSpaceUsed[MEMORY_SORT_SPACE_TYPE - 1][idx]); @@ -1190,6 +1210,7 @@ cdbexplain_depositStatsToNode(PlanState *planstate, CdbExplain_RecvStatCtx *ctx) cdbexplain_depStatAcc_upd(&totalWorkfileCreated, (rsi->workfileCreated ? 1 : 0), rsh, rsi, nsi); cdbexplain_depStatAcc_upd(&peakMemBalance, rsi->peakMemBalance, rsh, rsi, nsi); cdbexplain_depStatAcc_upd(&totalPartTableScanned, rsi->numPartScanned, rsh, rsi, nsi); + cdbexplain_depStatAcc_upd(&shareinputwait, rsi->shareinputwait, rsh, rsi, nsi); if (rsi->sortMethod < NUM_SORT_METHOD && rsi->sortMethod != UNINITIALIZED_SORT && rsi->sortSpaceType != UNINITIALIZED_SORT_SPACE_TYPE) { Assert(rsi->sortSpaceType <= NUM_SORT_SPACE_TYPE); @@ -1210,6 +1231,7 @@ cdbexplain_depositStatsToNode(PlanState *planstate, CdbExplain_RecvStatCtx *ctx) ns->totalWorkfileCreated = totalWorkfileCreated.agg; ns->peakMemBalance = peakMemBalance.agg; ns->totalPartTableScanned = totalPartTableScanned.agg; + ns->shareinputwait = shareinputwait.agg; for (int idx = 0; idx < NUM_SORT_METHOD; ++idx) { ns->sortSpaceUsed[MEMORY_SORT_SPACE_TYPE - 1][idx] = sortSpaceUsed[MEMORY_SORT_SPACE_TYPE - 1][idx].agg; @@ -1887,6 +1909,51 @@ cdbexplain_showExecStats(struct PlanState *planstate, ExplainState *es) } } + /* + * Print how long a cross-slice ShareInputScan blocked waiting for another + * slice. + * + * This is aggregated rather than left to the per-worker extra message + * text, because that text is selected by memory and row-count criteria + * (see cdbexplain_depositStatsToNode): with a skewed wait it would report + * an arbitrary worker rather than the one that actually blocked. Showing + * the max, its segment, and the average makes the skew itself visible. + * + * Every cross-slice consumer pays some handshake cost, so only report a + * wait that is material -- otherwise each such node would carry a + * "0.000 ms" line of pure noise. + */ +#define SHAREINPUT_WAIT_REPORT_THRESHOLD_SEC 0.001 + + if (T_ShareInputScanState == planstate->type && + ns->shareinputwait.vmax >= SHAREINPUT_WAIT_REPORT_THRESHOLD_SEC) + { + double wait_avg = cdbexplain_agg_avg(&ns->shareinputwait); + + cdbexplain_formatSeg(segbuf, sizeof(segbuf), ns->shareinputwait.imax, + ns->ninst); + + if (es->format == EXPLAIN_FORMAT_TEXT) + { + appendStringInfoSpaces(es->str, es->indent * 2); + appendStringInfo(es->str, + "Cross-slice wait: %.3f ms max%s, %.3f ms avg x %d workers.\n", + ns->shareinputwait.vmax * 1000.0, segbuf, + wait_avg * 1000.0, ns->shareinputwait.vcnt); + } + else + { + ExplainOpenGroup("cross-slice-wait", "cross-slice-wait", true, es); + ExplainPropertyFloat("Max Wait (ms)", + ns->shareinputwait.vmax * 1000.0, 3, es); + ExplainPropertyInteger("Max Wait Segment", + ns->shareinputwait.imax, es); + ExplainPropertyFloat("Avg Wait (ms)", wait_avg * 1000.0, 3, es); + ExplainPropertyInteger("Workers", ns->shareinputwait.vcnt, es); + ExplainCloseGroup("cross-slice-wait", "cross-slice-wait", true, es); + } + } + /* * Print number of partitioned tables scanned for dynamic scans. */ diff --git a/src/backend/executor/nodeShareInputScan.c b/src/backend/executor/nodeShareInputScan.c index 186664d0a26..e8446e136b7 100644 --- a/src/backend/executor/nodeShareInputScan.c +++ b/src/backend/executor/nodeShareInputScan.c @@ -39,6 +39,7 @@ #include "executor/executor.h" #include "executor/nodeShareInputScan.h" #include "miscadmin.h" +#include "portability/instr_time.h" #include "utils/faultinjector.h" #include "utils/gp_alloc.h" #include "utils/tuplesort.h" @@ -321,7 +322,20 @@ ExecSliceDependencyShareInputScan(ShareInputScanState *node) EState *estate = node->ss.ps.state; if(sisc->driver_slice >= 0 && sisc->driver_slice == currentSliceId) { - shareinput_reader_waitready(node->share_lk_ctxt, sisc->share_id, estate->es_plannedstmt->planGen); + double waited_sec; + + shareinput_reader_waitready(node->share_lk_ctxt, sisc->share_id, + estate->es_plannedstmt->planGen, + &node->waitready_time); + + /* + * Roll the wait up to the query level so the stats collector can + * report it (it only reads query-level, root-node instrumentation). + * Keep the longest wait seen on this segment. + */ + waited_sec = INSTR_TIME_GET_DOUBLE(node->waitready_time); + if (waited_sec > estate->es_cross_slice_wait) + estate->es_cross_slice_wait = waited_sec; } } @@ -624,6 +638,41 @@ static void fi_close_created_fds(int *fds, char *file_prefix, int num) * that can cause deadlocks (OPT-2690). */ +/* + * Context for the errcontext callback installed while blocked on a + * cross-slice handshake. A query that never gets its handshake is killed by + * statement_timeout, so it produces no EXPLAIN ANALYZE output and no + * completion log line -- the elapsed wait would be lost entirely. Reporting + * it through errcontext puts it into the cancellation message itself, which + * is the only channel that survives. + */ +typedef struct shareinput_wait_errctx +{ + int share_id; + int slice_id; + bool is_reader; + instr_time starttime; +} shareinput_wait_errctx; + +static void +shareinput_wait_errcontext_callback(void *arg) +{ + shareinput_wait_errctx *ctx = (shareinput_wait_errctx *) arg; + instr_time now; + + INSTR_TIME_SET_CURRENT(now); + INSTR_TIME_SUBTRACT(now, ctx->starttime); + + if (ctx->is_reader) + errcontext("ShareInputScan consumer (share_id=%d) in slice %d blocked %.3f ms waiting for the producer slice to publish", + ctx->share_id, ctx->slice_id, + INSTR_TIME_GET_MILLISEC(now)); + else + errcontext("ShareInputScan producer (share_id=%d) in slice %d blocked %.3f ms waiting for consumer slices to finish reading", + ctx->share_id, ctx->slice_id, + INSTR_TIME_GET_MILLISEC(now)); +} + /* * shareinput_reader_waitready * @@ -633,12 +682,17 @@ static void fi_close_created_fds(int *fds, char *file_prefix, int num) * This is a blocking operation. */ void -shareinput_reader_waitready(void *ctxt, int share_id, PlanGenerator planGen) +shareinput_reader_waitready(void *ctxt, int share_id, PlanGenerator planGen, + instr_time *waited) { struct pollfd fds[1]; int nfds = 0; char a; ShareInput_Lk_Context *pctxt = (ShareInput_Lk_Context *) ctxt; + instr_time starttime; + instr_time endtime; + shareinput_wait_errctx waitctx; + ErrorContextCallback errcallback; RegisterXactCallbackOnce(XCallBack_ShareInput_FIFO, pctxt); #ifdef FAULT_INJECTOR @@ -683,6 +737,18 @@ shareinput_reader_waitready(void *ctxt, int share_id, PlanGenerator planGen) fds[0].fd = pctxt->readyfd; fds[0].events = POLLIN; nfds++; + + INSTR_TIME_SET_CURRENT(starttime); + + waitctx.share_id = share_id; + waitctx.slice_id = currentSliceId; + waitctx.is_reader = true; + waitctx.starttime = starttime; + errcallback.callback = shareinput_wait_errcontext_callback; + errcallback.arg = (void *) &waitctx; + errcallback.previous = error_context_stack; + error_context_stack = &errcallback; + while(1) { CHECK_FOR_INTERRUPTS(); @@ -730,6 +796,14 @@ shareinput_reader_waitready(void *ctxt, int share_id, PlanGenerator planGen) share_id, currentSliceId, save_errno); } } + + error_context_stack = errcallback.previous; + + INSTR_TIME_SET_CURRENT(endtime); + INSTR_TIME_ACCUM_DIFF(*waited, endtime, starttime); + + elog(DEBUG1, "SISC READER (shareid=%d, slice=%d): waited %.3f ms for the producer", + share_id, currentSliceId, INSTR_TIME_GET_MILLISEC(*waited)); } /* @@ -884,6 +958,10 @@ shareinput_writer_waitdone(void *ctxt, int share_id, int nsharer_xslice) ShareInput_Lk_Context *pctxt = (ShareInput_Lk_Context *) ctxt; struct pollfd fds[1]; int nfds = 0; + instr_time starttime; + instr_time waited; + shareinput_wait_errctx waitctx; + ErrorContextCallback errcallback; if (pctxt->donefd < 0) return; @@ -897,6 +975,18 @@ shareinput_writer_waitdone(void *ctxt, int share_id, int nsharer_xslice) fds[0].fd = pctxt->donefd; fds[0].events = POLLIN; nfds++; + + INSTR_TIME_SET_CURRENT(starttime); + + waitctx.share_id = share_id; + waitctx.slice_id = currentSliceId; + waitctx.is_reader = false; + waitctx.starttime = starttime; + errcallback.callback = shareinput_wait_errcontext_callback; + errcallback.arg = (void *) &waitctx; + errcallback.previous = error_context_stack; + error_context_stack = &errcallback; + while(ack_needed > 0) { CHECK_FOR_INTERRUPTS(); @@ -931,8 +1021,14 @@ shareinput_writer_waitdone(void *ctxt, int share_id, int nsharer_xslice) } } - elog(DEBUG1, "SISC WRITER (shareid=%d, slice=%d): Writer received all %d reader done notifications", - share_id, currentSliceId, nsharer_xslice - pctxt->zcnt); + error_context_stack = errcallback.previous; + + INSTR_TIME_SET_CURRENT(waited); + INSTR_TIME_SUBTRACT(waited, starttime); + + elog(DEBUG1, "SISC WRITER (shareid=%d, slice=%d): Writer received all %d reader done notifications after %.3f ms", + share_id, currentSliceId, nsharer_xslice - pctxt->zcnt, + INSTR_TIME_GET_MILLISEC(waited)); shareinput_clean_lk_ctxt(ctxt); UnregisterXactCallbackOnce(XCallBack_ShareInput_FIFO, (void *) ctxt); diff --git a/src/include/nodes/execnodes.h b/src/include/nodes/execnodes.h index 0c6692e9eac..89f44a762cc 100644 --- a/src/include/nodes/execnodes.h +++ b/src/include/nodes/execnodes.h @@ -661,6 +661,15 @@ typedef struct EState /* Should the executor skip past the alien plan nodes */ bool eliminateAliens; + + /* + * Longest time (in seconds) any cross-slice ShareInputScan consumer in + * this query spent blocked waiting for its producer slice to publish. + * Rolled up here per query per segment so the stats collector can report + * it query-level; yagpcc then takes the max across segments, exposing + * slice-to-slice wait skew. Kept last in the struct to minimize ABI churn. + */ + double es_cross_slice_wait; } EState; struct PlanState; @@ -2492,11 +2501,25 @@ typedef struct ShareInputScanState bool freed; /* is this node already freed? */ char *share_bufname_prefix; + + /* + * How long this consumer blocked waiting for the producer slice to + * publish its tuplestore. The wait is invisible in the plan otherwise, + * which makes a mis-wired cross-slice share look like a slow node rather + * than a node blocked on another slice. Reported by EXPLAIN ANALYZE. + * + * The producer's own wait (for consumers to finish) is not tracked here: + * the producer side of a cross-slice share is the Material or Sort node + * below, and that wait happens during node shutdown anyway, after this + * node's stats have been sent to the QD. It is logged instead. + */ + instr_time waitready_time; /* consumer waited for producer's tuplestore */ } ShareInputScanState; /* XXX Should move into buf file */ extern void *shareinput_init_lk_ctxt(int share_id); -extern void shareinput_reader_waitready(void *, int share_id, PlanGenerator planGen); +extern void shareinput_reader_waitready(void *, int share_id, PlanGenerator planGen, + instr_time *waited); extern void shareinput_writer_notifyready(void *, int share_id, int nsharer_xslice_notify_ready, PlanGenerator planGen); extern void shareinput_reader_notifydone(void *, int share_id); extern void shareinput_writer_waitdone(void *, int share_id, int nsharer_xslice_wait_done); diff --git a/src/test/regress/expected/shared_scan.out b/src/test/regress/expected/shared_scan.out index 3a4fddef1ce..cb7a5b5de49 100644 --- a/src/test/regress/expected/shared_scan.out +++ b/src/test/regress/expected/shared_scan.out @@ -445,3 +445,42 @@ from gp_segment_configuration where role = 'p' and content = -1; Success: (1 row) + +-- Cross-slice ShareInputScan wait accounting. +-- +-- A consumer that blocks waiting for a slow producer slice reports the wait +-- in EXPLAIN ANALYZE ("Cross-slice wait: N ms max ..."). Force a +-- deterministic, above-threshold wait by making the producer sleep, and +-- assert the line appears. The wrapper hides the non-deterministic timing +-- value, returning only whether the line is present, so the test is stable. +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; +create function sisw_wait_reported(q text) returns boolean as $fn$ +declare ln text; +begin + for ln in execute 'explain (analyze, timing off, costs off) ' || q loop + if strpos(ln, 'Cross-slice wait:') > 0 then return true; end if; + end loop; + return false; +end; $fn$ language plpgsql; +set optimizer = off; +set gp_cte_sharing = on; +select sisw_wait_reported($q$ + 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 +$q$); + sisw_wait_reported +-------------------- + t +(1 row) + +reset gp_cte_sharing; +reset optimizer; +drop function sisw_wait_reported(text); +drop table sisw_foo, sisw_bar; diff --git a/src/test/regress/expected/shared_scan_optimizer.out b/src/test/regress/expected/shared_scan_optimizer.out index a1371f86f6d..17130f19645 100644 --- a/src/test/regress/expected/shared_scan_optimizer.out +++ b/src/test/regress/expected/shared_scan_optimizer.out @@ -495,3 +495,42 @@ from gp_segment_configuration where role = 'p' and content = -1; Success: (1 row) + +-- Cross-slice ShareInputScan wait accounting. +-- +-- A consumer that blocks waiting for a slow producer slice reports the wait +-- in EXPLAIN ANALYZE ("Cross-slice wait: N ms max ..."). Force a +-- deterministic, above-threshold wait by making the producer sleep, and +-- assert the line appears. The wrapper hides the non-deterministic timing +-- value, returning only whether the line is present, so the test is stable. +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; +create function sisw_wait_reported(q text) returns boolean as $fn$ +declare ln text; +begin + for ln in execute 'explain (analyze, timing off, costs off) ' || q loop + if strpos(ln, 'Cross-slice wait:') > 0 then return true; end if; + end loop; + return false; +end; $fn$ language plpgsql; +set optimizer = off; +set gp_cte_sharing = on; +select sisw_wait_reported($q$ + 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 +$q$); + sisw_wait_reported +-------------------- + t +(1 row) + +reset gp_cte_sharing; +reset optimizer; +drop function sisw_wait_reported(text); +drop table sisw_foo, sisw_bar; diff --git a/src/test/regress/sql/shared_scan.sql b/src/test/regress/sql/shared_scan.sql index f7a4a06d186..d9d55e37de6 100644 --- a/src/test/regress/sql/shared_scan.sql +++ b/src/test/regress/sql/shared_scan.sql @@ -238,3 +238,37 @@ from ( reset optimizer_parallel_union; select gp_inject_fault_infinite('material_pre_tuplestore_flush', 'reset', dbid) from gp_segment_configuration where role = 'p' and content = -1; + +-- Cross-slice ShareInputScan wait accounting. +-- +-- A consumer that blocks waiting for a slow producer slice reports the wait +-- in EXPLAIN ANALYZE ("Cross-slice wait: N ms max ..."). Force a +-- deterministic, above-threshold wait by making the producer sleep, and +-- assert the line appears. The wrapper hides the non-deterministic timing +-- value, returning only whether the line is present, so the test is stable. +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; +create function sisw_wait_reported(q text) returns boolean as $fn$ +declare ln text; +begin + for ln in execute 'explain (analyze, timing off, costs off) ' || q loop + if strpos(ln, 'Cross-slice wait:') > 0 then return true; end if; + end loop; + return false; +end; $fn$ language plpgsql; +set optimizer = off; +set gp_cte_sharing = on; +select sisw_wait_reported($q$ + 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 +$q$); +reset gp_cte_sharing; +reset optimizer; +drop function sisw_wait_reported(text); +drop table sisw_foo, sisw_bar; From 3b12cf4be2078d9431fc52625309346cc3a74086 Mon Sep 17 00:00:00 2001 From: Alena Rybakina Date: Tue, 28 Jul 2026 21:49:33 +0300 Subject: [PATCH 2/2] gp_stats_collector: expose cross-slice ShareInputScan wait 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. --- gpcontrib/gp_stats_collector/metric.md | 14 ++++++++++++ .../protos/gpsc_metrics.proto | 22 +++++++++++++++++++ .../gp_stats_collector/src/ProtoUtils.cpp | 17 ++++++++++++++ .../gp_stats_collector/src/log/LogSchema.h | 1 + 4 files changed, 54 insertions(+) diff --git a/gpcontrib/gp_stats_collector/metric.md b/gpcontrib/gp_stats_collector/metric.md index 3ef8de079a0..791411603e5 100644 --- a/gpcontrib/gp_stats_collector/metric.md +++ b/gpcontrib/gp_stats_collector/metric.md @@ -69,6 +69,7 @@ submit -> ExecutorStart() -> start -> ExecutorRun() -> ExecutorFinish() -> end - | `blk_write_time` | double | E, D | ABS | + | Node | + | + | seconds | Time writing data blocks | | `inherited_calls` | uint64 | E, D | ABS | - | Node | + | + | count | Nested query count (GPSC-specific) | | `inherited_time` | double | E, D | ABS | - | Node | + | + | seconds | Nested query time (GPSC-specific) | +| `cross_slice_wait_ms` | double | E, D | ABS | + | Node | + | + | ms** | Longest cross-slice ShareInputScan wait (GPSC-specific) | | **NetworkStat (sent)** | | | | | | | | | | | `sent.total_bytes` | uint32 | D | ABS | - | Node | + | + | bytes | Bytes sent, including headers | | `sent.tuple_bytes` | uint32 | D | ABS | - | Node | + | + | bytes | Bytes of pure tuple-data sent | @@ -122,5 +123,18 @@ submit -> ExecutorStart() -> start -> ExecutorRun() -> ExecutorFinish() -> end - | `dbid` | int32 | All | ABS | - | Node | + | + | id | Database ID | | `segment_index` | int32 | All | ABS | - | Node | + | + | id | Segment index (-1=coordinator) | +**\*\* `cross_slice_wait_ms`** is how long a cross-slice ShareInputScan consumer +blocked waiting for its producer slice to publish the shared tuplestore. Read as +max across segments against the average: a wide gap means the producer finished +unevenly, not that the consumer is 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. + +Two things set it apart from the rest of the table. It is reported in milliseconds +rather than seconds -- the unit is part of the field name, so the wire contract +stays unambiguous. And it is the one `MetricInstrumentation` field filled without +instrumentation enabled: the executor measures the wait either way. A zero wait is +not reported. + --- diff --git a/gpcontrib/gp_stats_collector/protos/gpsc_metrics.proto b/gpcontrib/gp_stats_collector/protos/gpsc_metrics.proto index e124fa63a53..e43495cb0a3 100644 --- a/gpcontrib/gp_stats_collector/protos/gpsc_metrics.proto +++ b/gpcontrib/gp_stats_collector/protos/gpsc_metrics.proto @@ -175,6 +175,28 @@ message MetricInstrumentation { uint64 inherited_calls = 22; /* the number of executed sub-queries */ double inherited_time = 23; /* total time spend on inherited execution */ InterconnectStat interconnect = 24; + /* + * Longest time a cross-slice ShareInputScan consumer spent blocked waiting + * for its producer slice to publish the shared tuplestore. Scope is the + * reporting process (one per slice), not the segment as a whole. Unlike + * the other timings here it is in milliseconds, hence the suffix. + * + * The wait says how long one slice sat idle on another, which is worth + * watching well beyond a mis-wired share: + * - aggregated as max across segments and compared against the average, + * it measures how unevenly the producer finished -- large max/avg gap + * means a skewed producer, not a slow consumer; + * - it splits "this node is slow" from "this node is waiting", so time + * is not attributed to the consumer that merely blocked; + * - it grows when the producer slice is starved of CPU or interconnect, + * making it an early signal of cluster-wide contention; + * - it is the only trace left by a query killed on statement_timeout + * while blocked here, where per-node instrumentation never arrives. + * + * Kept in sync by hand with protos/yagpcc_metrics.proto in the + * yagp_hooks_collector repo, which this directory forked from. + */ + double cross_slice_wait_ms = 25; } message SpillInfo { diff --git a/gpcontrib/gp_stats_collector/src/ProtoUtils.cpp b/gpcontrib/gp_stats_collector/src/ProtoUtils.cpp index 503da797a3c..ce348adb99c 100644 --- a/gpcontrib/gp_stats_collector/src/ProtoUtils.cpp +++ b/gpcontrib/gp_stats_collector/src/ProtoUtils.cpp @@ -250,6 +250,23 @@ set_gp_metrics(gpsc::GPMetrics *metrics, QueryDesc *query_desc, set_metric_instrumentation(metrics->mutable_instrumentation(), query_desc, nested_calls, nested_time); } + + /* + * Longest cross-slice ShareInputScan wait seen by this process, rolled up + * to the query level in the executor. Reported in milliseconds; yagpcc + * takes the max across segments, so a large gap against the average marks + * a skewed producer slice rather than a slow consumer. + * + * Set outside the block above on purpose: the executor measures the wait + * regardless of instrumentation, and a query killed by statement_timeout -- + * the case with no other trace left -- may well run without it. Only a + * non-zero wait is reported, so queries that never waited do not get an + * otherwise empty instrumentation submessage. + */ + if (query_desc->estate && query_desc->estate->es_cross_slice_wait > 0) + metrics->mutable_instrumentation()->set_cross_slice_wait_ms( + query_desc->estate->es_cross_slice_wait * 1000.0); + fill_self_stats(metrics->mutable_systemstat()); metrics->mutable_systemstat()->set_runningtimeseconds( time(NULL) - metrics->mutable_systemstat()->runningtimeseconds()); diff --git a/gpcontrib/gp_stats_collector/src/log/LogSchema.h b/gpcontrib/gp_stats_collector/src/log/LogSchema.h index e03b619876c..fea174e55a4 100644 --- a/gpcontrib/gp_stats_collector/src/log/LogSchema.h +++ b/gpcontrib/gp_stats_collector/src/log/LogSchema.h @@ -112,6 +112,7 @@ inline constexpr std::array log_tbl_desc = { LogDesc{"instrumentation_blk_write_time", "query_metrics.instrumentation.blk_write_time", FLOAT8OID}, LogDesc{"instrumentation_startup_time", "query_metrics.instrumentation.startup_time", FLOAT8OID}, LogDesc{"instrumentation_inherited_time", "query_metrics.instrumentation.inherited_time", FLOAT8OID}, + LogDesc{"instrumentation_cross_slice_wait_ms", "query_metrics.instrumentation.cross_slice_wait_ms", FLOAT8OID}, LogDesc{"datetime", "datetime", TIMESTAMPTZOID}, LogDesc{"submit_time", "submit_time", TIMESTAMPTZOID}, LogDesc{"start_time", "start_time", TIMESTAMPTZOID},