[Sandbox] PPL profile: LATE_MATERIALIZATION stage emits no physical plan and no metrics

[alchemist51]

Summary

POST _plugins/_ppl with {"profile": true} returns rich per-stage diagnostics for SHARD_FRAGMENT and COORDINATOR_REDUCE stages — a physical_plan string and a ~60-field data_node_metrics block per task. The LATE_MATERIALIZATION stage returns neither. When that stage dominates wall clock, the profile reports where time went only at whole-stage granularity, and root-causing requires reading engine source.

Evidence

Same query, four stages. Stage 2 is 98.5% of total time and the only stage with no
diagnostics at all:

{
  "stage_id": 2,
  "execution_type": "LATE_MATERIALIZATION",
  "elapsed_ms": 5037,
  "rows_processed": 0,
  "tasks": [
    {
      "node": "2.0",
      "state": "FINISHED",
      "elapsed_ms": 5037
    }
  ]
}

Contrast a SHARD_FRAGMENT task in the same response, which carries both
(data_node_metrics abridged — the real block has ~60 fields):

{
  "node": "<node-id>/shard[0]",
  "state": "FINISHED",
  "elapsed_ms": 78,
  "physical_plan": "SortPreservingMergeExec: [...] fetch=50\n  SortExec: TopK(fetch=50) ...\n    QueryShardExec: partitions=2, segments=14, ordering=unsorted\n",
  "data_node_metrics": {
    "parquet_read_time": 810312,
    "bytes_scanned": 30746442,
    "rows_pruned_by_page_index": 9669488,
    "row_groups_skipped": 12,
    "pages_pruned": 847,
    "pages_total": 871,
    "elapsed_compute": 45083437
  }
}

Secondary problem: reported elapsed does not reconcile with timestamps

Where data_node_metrics is present, its start_timestamp / end_timestamp (ns) span far less than the task's elapsed_ms:

Stage	Timestamp span	Reported elapsed_ms	Unexplained
1 (COORDINATOR_REDUCE)	33.4 ms	79	45.6 ms
3 (COORDINATOR_REDUCE, wraps stage 2)	117.5 ms	5038	4920.5 ms

Stage 3 wraps stage 2, so ~4.9 s is time the profile attributes to a stage while its own instrumentation accounts for 117 ms of it. Whether the remainder is queueing, blocking on a child stage, or genuinely uninstrumented work is not determinable from the output.

Also missing: which rows/bytes the LM stage actually touched

rows_processed: 0 on a stage that materialized a row is at best confusing. There is no counter for the bytes or column chunks the fetch path read — precisely the number needed to detect the full-column-chunk problem in the companion issue.

Impact

Diagnosing a 5-second single-row query required checking out OpenSearch, arrow-rs, and datafusion and tracing four call sites by hand. The profile correctly said which stage was slow and gave no information about why. For anyone without local source checkouts — including customers and most on-call paths — this is a dead end.

Requested

1. Emit physical_plan for LATE_MATERIALIZATION tasks, as other stage types do.
2. Emit data_node_metrics for the fetch path. Minimum useful set, mirroring
   existing scan-path metric names:
   • bytes_scanned, parquet_read_time, files_opened, row_groups_processed
   • a count of column chunks fetched and whether the offset index was
     available (directly distinguishes page-level from whole-chunk fetch)
   • metadata_load_time, elapsed_compute
3. Populate rows_processed for the stage, or drop the field where not meaningful.
4. Reconcile elapsed_ms with instrumented time, or split it into explicit
   queue_time / wait_time / compute_time so the gap is legible rather than
   silent.

Notes

"profile": true on _plugins/_ppl appears to be undocumented — it is not in the PPL docs and was found by trial. It returns summary.total_time_ms, per-phase timings (analyze/optimize/execute/format), plan.full_plan, plan.query_id, and the per-stage tree described above. Worth documenting independently of this issue; it is the fastest plan-capture path on a managed domain, where tailing node logs for RustLoggerBridge DEBUG output is not available.

The query_id returned in plan does allow correlating a run against node logs where log access exists — but the Calcite-level full_plan does not include the DataFusion ordering=sorted=[...] / ordering=unsorted line, so sort-propagation questions still require the log route.

Related

• Companion issue: late-materialization fetch path reads full column chunks because the offset index is never loaded — found by source reading, not profiling, because of this gap

[finnegancarroll]

Thanks for raising this @alchemist51 . The missing LM support is definitely a gap in profile output. I'll take a look at instrumenting this new stage with the following:

• Emit physical_plan for LM tasks (the fetch-path DataFusion plan)
• Emit data_node_metrics for the fetch path (bytes_scanned, parquet_read_time, column_chunks_fetched, offset_index_available)
• Populate rows_processed for LM stage (or drop the field)

The difference between elapsed_ms and timestamps is due to elapsed_ms being captured as wall clock time on the coordinator while timestamps are native to datafusion execution metrics. Everything outside of datafusion execution accounts for the discrepancy here (queuing, streaming results, context management, ect).

split into queue_time / wait_time / compute_time, or at least document why the gap exists

I'll look at capturing some of these blindspots and better document this area.