DataSourceExec metrics explanation

[debajyoti-truefoundry]

{
  "datafusion.metrics.row_groups_pruned_statistics": "0",
  "datafusion.metrics.file_open_errors": "0",
  "code.filepath": "src/server/app_state.rs",
  "datafusion.metrics.page_index_eval_time": "936.547µs",
  "datafusion.metrics.row_pushdown_eval_time": "305.394559ms",
  "datafusion.metrics.metadata_load_time": "38.869829ms",
  "datafusion.preview": "",
  "datafusion.emission_type": "Incremental",
  "datafusion.metrics.bytes_scanned": "1209599324",
  "datafusion.node": "DataSourceExec: file_groups={8 groups: [[...]]}, projection=[...], file_type=parquet, predicate=, required_guarantees=[]",
  "datafusion.metrics.end_timestamp": "2025-06-26 12:56:20.582199498 UTC",
  "datafusion.metrics.elapsed_compute": "8ns",
  "datafusion.metrics.bloom_filter_eval_time": "3.04375ms",
  "datafusion.metrics.statistics_eval_time": "3.874945ms",
  "datafusion.metrics.output_rows": "913521",
  "thread.name": "cpu-runtime",
  "datafusion.metrics.time_elapsed_processing": "2.209661124s",
  "datafusion.metrics.pushdown_rows_pruned": "44461381",
  "datafusion.metrics.row_groups_matched_statistics": "85",
  "datafusion.metrics.pushdown_rows_matched": "46243794",
  "datafusion.metrics.file_scan_errors": "0",
  "datafusion.metrics.page_index_rows_matched": "45374902",
  "datafusion.metrics.start_timestamp": "2025-06-26 12:56:20.172305562 UTC",
  "datafusion.metrics.predicate_evaluation_errors": "0",
  "datafusion.metrics.time_elapsed_scanning_until_data": "2.030212717s",
  "datafusion.metrics.time_elapsed_opening": "16.665201ms",
  "datafusion.metrics.num_predicate_creation_errors": "0",
  "code.namespace": "server::app_state",
  "datafusion.partitioning": "UnknownPartitioning(8)",
  "datafusion.boundedness": "Bounded",
  "datafusion.metrics.time_elapsed_scanning_total": "2.286310309s",
  "datafusion.metrics.page_index_rows_pruned": "0",
  "datafusion.metrics.row_groups_pruned_bloom_filter": "0",
  "datafusion.metrics.row_groups_matched_bloom_filter": "0",
  "code.lineno": 74,
  "thread.id": 10,
  "busy_ns": 345942296,
  "idle_ns": 64056220
}

time_elapsed_opening
time_elapsed_scanning_total
I can see that the above metrics are documented in this section.

Could someone please explain the following metrics as well? 🙏
time_elapsed_processing
time_elapsed_scanning_until_data

[2010YOUY01]

time_elapsed_opening for example, unfortunately we have to search for this name in the codebase, and then follow several indirections to find the comment to explain this metrics:

datafusion/datafusion/datasource/src/file_stream.rs

Lines 441 to 451 in 9f3cc7b

	/// Wall clock time elapsed for file opening.
	///
	/// Time between when [`FileOpener::open`] is called and when the
	/// [`FileStream`] receives a stream for reading.
	///
	/// If there are multiple files being scanned, the stream
	/// will open the next file in the background while scanning the
	/// current file. This metric will only capture time spent opening
	/// while not also scanning.
	/// [`FileStream`]: <https://github.com/apache/datafusion/blob/main/datafusion/core/src/datasource/physical_plan/file_stream.rs>
	pub time_opening: StartableTime,

This is not ideal, it would be great we can have a auto-generated doc page, to document all available metrics. I'll come up with an issue later.

[debajyoti-truefoundry]

Thanks for your response. I have a follow-up question.

For time_scanning_total,

/// Sum of time between when the [FileStream] requests data from
/// the stream and when a [RecordBatch] is produced for all
/// record batches in the stream. Note that this metric also
/// includes the time of the parent operator's execution.

Above, it says that it includes the time of the parent operator's execution.

ProjectionExec: expr=...], metrics=[output_rows=10, elapsed_compute=3.06µs]
  SortPreservingMergeExec: [Timestamp@14 ASC NULLS LAST], fetch=10, metrics=[output_rows=10, elapsed_compute=94.06µs]
    SortExec: TopK(fetch=10), expr=[Timestamp@14 ASC NULLS LAST], preserve_partitioning=[true], metrics=[output_rows=80, elapsed_compute=12.08824ms, row_replacements=524]
      ProjectionExec: expr=[...], metrics=[output_rows=492435, elapsed_compute=1.642723ms]
        AggregateExec: mode=FinalPartitioned, gby=[SpanId@0 as SpanId], aggr=[...], metrics=[output_rows=492435, elapsed_compute=3.782239042s, spill_count=0, spilled_bytes=0, spilled_rows=0, peak_mem_used=1391660979]
          CoalesceBatchesExec: target_batch_size=20000, metrics=[output_rows=492435, elapsed_compute=833.513µs]
            RepartitionExec: partitioning=Hash([SpanId@0], 8), input_partitions=8, metrics=[fetch_time=3.348780759s, repartition_time=74.558637ms, send_time=191.866672ms]
              AggregateExec: mode=Partial, gby=[SpanId@2 as SpanId], aggr=[...], metrics=[output_rows=492435, elapsed_compute=2.739883773s, spill_count=0, spilled_bytes=0, spilled_rows=0, skipped_aggregation_rows=178127, peak_mem_used=905512155]
                CoalesceBatchesExec: target_batch_size=20000, metrics=[output_rows=492435, elapsed_compute=65.121µs]
                  FilterExec: TraceId@2 = fb09d0c9b49136bb161464b3e32c5083 AND ParentSpanId@4 = 662b7388122dfb79 AND Timestamp@0 >= 1744702200000000 AND TsBucketStart@1 >= 1745712000, projection=[...], metrics=[output_rows=492435, elapsed_compute=3.906094ms]
                    DeltaScan, metrics=[files_pruned=96, files_scanned=205]
                      DataSourceExec: file_groups={8 groups: [[...]]}, projection=[...], file_type=parquet, predicate=..., required_guarantees=[...], metrics=[output_rows=492435, elapsed_compute=8ns, bytes_scanned=369875275, file_open_errors=0, file_scan_errors=0, num_predicate_creation_errors=0, page_index_rows_matched=5863737, page_index_rows_pruned=0, predicate_evaluation_errors=0, pushdown_rows_matched=12712344, pushdown_rows_pruned=5371302, row_groups_matched_bloom_filter=10, row_groups_matched_statistics=205, row_groups_pruned_bloom_filter=195, row_groups_pruned_statistics=0, bloom_filter_eval_time=8.481976ms, metadata_load_time=60.123782ms, page_index_eval_time=306.984µs, row_pushdown_eval_time=28.323855ms, statistics_eval_time=4.302826ms, time_elapsed_opening=7.653019ms, time_elapsed_processing=582.67032ms, time_elapsed_scanning_total=3.243596916s, time_elapsed_scanning_until_data=398.202399ms]

For this query plan, what will be the parent operator? Is the parent operator part of the above query plan? Or in this case, the parent operator is the Parquet record batch reader itself?

[2010YOUY01]

My guess:
If data source is actually scanning in [0,10], [15,20]. During [10,15] it's not scanning because this datasource operator is not scheduled in the runtime, and its parents are using the CPU to do other computations.
This metric's reported time is 20 which includes the gap.

[debajyoti-truefoundry]

Seems like this is the case.

Ref: https://discord.com/channels/885562378132000778/1388186871594745956/1388748472491970662