[BUG] Mustang Profile API Inconsistencies

Inizia riproducendo la risposta del profilo con l'OpenSearch core fornito, i cluster settings, il composite data format e la PPL query. Confronta i tempi di profile.phases con profile.plan.planning_time_ms ed execution_time_ms; il lavoro è completato quando le metriche riportate sono coerenti o le loro differenze sono chiaramente spiegate.

What is the bug?
Profile response on Mustang has some confusing performance metrics:

• profile.phases.optimize.time_ms returns 0.0
• profile.phases.execute.time_ms != profile.plan.execution_time_ms
• profile.plan.planning_time_ms seems to not line up with profile.phases

How can one reproduce the bug?
Steps to reproduce the behavior:

1. Clone and run OpenSearch core

git clone https://github.com/opensearch-project/OpenSearch.git
./gradlew :run -Dsandbox.enabled=true \
    -Dtests.jvm.argline="-Dopensearch.experimental.feature.transport.stream.enabled=true" \
    -PinstalledPlugins="['arrow-base', 'arrow-flight-rpc', 'composite-engine', \
      'opensearch-job-scheduler:3.8.0.0-SNAPSHOT', 'analytics-engine', \
      'parquet-data-format', 'analytics-backend-datafusion', \
      'analytics-backend-lucene', 'opensearch-sql-plugin:3.8.0.0-SNAPSHOT']"

2. Update cluster settings

curl -X PUT localhost:9200/_cluster/settings -H 'Content-Type: application/json' -d '{
    "persistent": {
      "cluster.pluggable.dataformat": "composite"
    }
  }'
{"acknowledged":true,"persistent":{"cluster":{"pluggable":{"dataformat":"composite"}}},"transient":{}

curl -X PUT localhost:9200/test_data -H 'Content-Type: application/json' -d '{
    "settings": {
      "number_of_shards": 1,
      "number_of_replicas": 0,
      "pluggable.dataformat.enabled": true,
      "pluggable.dataformat": "composite",
      "composite.primary_data_format": "parquet",
      "composite.secondary_data_formats": ["lucene"]
    }
  }'
{"acknowledged":true,"shards_acknowledged":true,"index":"test_data"}

3. Load sample data and run a profile query.

curl -X POST "localhost:9200/_plugins/_ppl" \ 
  -H "Content-Type: application/json" \
  -d '{"query": "SOURCE = `test_data` | where hour_24 > 2 | STATS count() | head 1", "profile": true}'
{
  "profile": {
    "summary": {
      "total_time_ms": 23.5
    },
    "phases": {
      "analyze": {
        "time_ms": 2.36
      },
      "optimize": {
        "time_ms": 0.0
      },
      "execute": {
        "time_ms": 18.82
      },
      "format": {
        "time_ms": 0.02
      }
    },
    "plan": {
      "query_id": "0400527c-30f7-4a73-a7e4-1178946bdc69",
      "full_plan": [
        "OpenSearchAggregate(group=[{}], count()=[COUNT()], mode=[SINGLE], viableBackends=[[datafusion]])",
        "  OpenSearchFilter(condition=[ANNOTATED_PREDICATE(id=0, backends=[datafusion], >($25, 2))], viableBackends=[[datafusion]])",
        "    OpenSearchTableScan(table=[[test_data]], viableBackends=[[lucene, datafusion]])"
      ],
      "planning_time_ms": 7,
      "execution_time_ms": 9,
      "stages": [
        {
          "stage_id": 0,
          "execution_type": "SHARD_FRAGMENT",
          "state": "SUCCEEDED",
          "start_ms": 1785783690331,
          "end_ms": 1785783690340,
          "elapsed_ms": 9,
          "rows_processed": 1,
          "tasks_completed": 1,
          "tasks_failed": 0,
          "fragment": [
            "OpenSearchAggregate(group=[{}], count()=[COUNT()], mode=[SINGLE], viableBackends=[[datafusion]])",
            "  OpenSearchFilter(condition=[ANNOTATED_PREDICATE(id=0, backends=[datafusion], >($25, 2))], viableBackends=[[datafusion]])",
            "    OpenSearchTableScan(table=[[test_data]], viableBackends=[[lucene, datafusion]])"
          ],
          "chosen_backend": "datafusion",
          "tasks": [
            {
              "node": "g2BqqwwGSnejwq5MObAX9Q/shard[0]",
              "state": "FINISHED",
              "elapsed_ms": 9,
              "data_node_metrics": {
                "selectivity": 0,
                "page_index_pages_pruned_pruned": 0,
                "pushdown_rows_pruned": 0,
                "start_timestamp": 1785783690335463000,
                "page_index_rows_pruned_matched": 1310517,
                "statistics_eval_time": 68292,
                "output_rows_skew": 0,
                "file_scan_errors": 0,
                "output_rows": 2457391,
                "page_index_pages_pruned_matched": 68,
                "page_index_eval_time": 22542,
                "row_pushdown_eval_time": 0,
                "time_elapsed_opening": 1022499,
                "limit_pruned_row_groups_pruned": 0,
                "end_timestamp": 1785783690337851000,
                "row_groups_pruned_statistics_matched": 7,
                "metadata_load_time": 409790,
                "num_predicate_creation_errors": 0,
                "output_bytes": 10565072,
                "files_ranges_pruned_statistics_pruned": 0,
                "files_opened": 10,
                "elapsed_compute": 476840,
                "output_batches": 335,
                "file_open_errors": 0,
                "time_elapsed_scanning_total": 5855504,
                "row_groups_pruned_statistics_pruned": 0,
                "pushdown_rows_matched": 0,
                "page_index_rows_pruned_pruned": 0,
                "time_elapsed_processing": 2031261,
                "bloom_filter_eval_time": 47877,
                "predicate_cache_inner_records": 0,
                "limit_pruned_row_groups_matched": 0,
                "predicate_evaluation_errors": 0,
                "bytes_scanned": 828069,
                "batches_split": 0,
                "row_groups_pruned_bloom_filter_matched": 7,
                "scan_efficiency_ratio": 0,
                "predicate_cache_records": 0,
                "files_processed": 10,
                "files_ranges_pruned_statistics_matched": 10,
                "time_elapsed_scanning_until_data": 4567168,
                "row_groups_pruned_bloom_filter_pruned": 0
              },
              "physical_plan": "AggregateExec: mode=Final, gby=[], aggr=[count(1) as count()]\n  CoalescePartitionsExec\n    AggregateExec: mode=Partial, gby=[], aggr=[count(1) as count()]\n      FilterExec: hour_24@0 > 2, projection=[]\n        DataSourceExec: file_groups={4 groups: [[Users/kjgandhi/work/OpenSearch/build/testclusters/runTask-0/data/nodes/0/indices/jnaZqsl0R8i7RYqbIQ71WA/0/parquet/_parquet_file_generation_b7.parquet:0..1849185, Users/kjgandhi/work/OpenSearch/build/testclusters/runTask-0/data/nodes/0/indices/jnaZqsl0R8i7RYqbIQ71WA/0/parquet/_parquet_file_generation_b9.parquet:0..787474, Users/kjgandhi/work/OpenSearch/build/testclusters/runTask-0/data/nodes/0/indices/jnaZqsl0R8i7RYqbIQ71WA/0/parquet/_parquet_file_generation_ba.parquet:0..251130, Users/kjgandhi/work/OpenSearch/build/testclusters/runTask-0/data/nodes/0/indices/jnaZqsl0R8i7RYqbIQ71WA/0/parquet/_parquet_file_generation_bb.parquet:0..256637, Users/kjgandhi/work/OpenSearch/build/testclusters/runTask-0/data/nodes/0/indices/jnaZqsl0R8i7RYqbIQ71WA/0/parquet/_parquet_file_generation_merged_87.parquet:0..73579144], [Users/kjgandhi/work/OpenSearch/build/testclusters/runTask-0/data/nodes/0/indices/jnaZqsl0R8i7RYqbIQ71WA/0/parquet/_parquet_file_generation_merged_87.parquet:73579144..150302714], [Users/kjgandhi/work/OpenSearch/build/testclusters/runTask-0/data/nodes/0/indices/jnaZqsl0R8i7RYqbIQ71WA/0/parquet/_parquet_file_generation_merged_87.parquet:150302714..216105406, Users/kjgandhi/work/OpenSearch/build/testclusters/runTask-0/data/nodes/0/indices/jnaZqsl0R8i7RYqbIQ71WA/0/parquet/_parquet_file_generation_merged_a3.parquet:0..10920878], [Users/kjgandhi/work/OpenSearch/build/testclusters/runTask-0/data/nodes/0/indices/jnaZqsl0R8i7RYqbIQ71WA/0/parquet/_parquet_file_generation_merged_a3.parquet:10920878..52189997, Users/kjgandhi/work/OpenSearch/build/testclusters/runTask-0/data/nodes/0/indices/jnaZqsl0R8i7RYqbIQ71WA/0/parquet/_parquet_file_generation_merged_b8.parquet:0..35454449]]}, projection=[hour_24], file_type=parquet, predicate=hour_24@51 > 2, pruning_predicate=hour_24_null_count@1 != row_count@2 AND hour_24_max@0 > 2, required_guarantees=[]\n"
            }
          ]
        }
      ]
    }
  },
  "schema": [
    {
      "name": "count()",
      "type": "bigint"
    }
  ],
  "datarows": [
    [
      1146865
    ]
  ],
  "total": 1,
  "size": 1
}

What is the expected behavior?

• profile.phases.optimize.time_ms returns 0.0
  Would expect optimize to take non-negligible time. The same query on non-AE path takes ~7ms for optimize phase (via profile, not analyze).

• profile.phases.execute.time_ms != profile.plan.execution_time_ms
  Would expect these two values to be identical, or at least similar. In this case, profile.phases.execute.time_ms was 18.82 and profile.plan.execution_time_ms was 9. This is too big of a gap with no explanation why. Could be related to profile.phases.optimize.time_ms returning 0.0.

• profile.plan.planning_time_ms seems to not line up with profile.phases
  Expecting some explanation to understand why profile.plan.planning_time_ms does not line up with profile.phases.analyze.time_ms and profile.phases.optimize.time_ms. If they are measuring different things/different for each engine, why is profile.phases included in the AE profile output?

What is your host/environment?

• OS: MacOS
• Version 26.5.1
• Plugins: Using SQL plugin with ongoing Analyze development

Do you have any additional context?
Test dataset is 10GB.