[BUG] Mustang Profile API Inconsistencies

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.

Start by reproducing the profile response with the provided OpenSearch core, cluster settings, composite data format, and PPL query. Compare profile.phases timings with profile.plan.planning_time_ms and execution_time_ms; done when the reported metrics are consistent or their differences are clearly explained.