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

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