Skip to content

Add query plans to profile output #128828

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 10 commits into from
Jun 25, 2025

Conversation

idegtiarenko
Copy link
Contributor

Query plan might be essential in order to understand how query is executed.
In order to see it one needs to enable TRACE logging in number of classes.
This might not be practical or even possible in a cluster running lots of queries.

This change adds output with executed plans to the query profile output, please see below:

Sample profile output
{
"took": 432,
"is_partial": false,
"documents_found": 5,
"values_loaded": 5,
"columns": [
  {
    "name": "language_code",
    "type": "long"
  }
],
"values": [
  [
    0
  ],
  [
    0
  ],
  [
    0
  ],
  [
    0
  ],
  [
    0
  ]
],
"profile": {
  "query": {
    "start_millis": 1748954775537,
    "stop_millis": 1748954775969,
    "took_millis": 432,
    "took_nanos": 432674263
  },
  "planning": {
    "start_millis": 1748954775537,
    "stop_millis": 1748954775727,
    "took_millis": 190,
    "took_nanos": 190547024
  },
  "drivers": [
    {
      "description": "data",
      "cluster_name": "runTask",
      "node_name": "runTask-0",
      "start_millis": 1748954775822,
      "stop_millis": 1748954775841,
      "took_nanos": 18628962,
      "cpu_nanos": 16571217,
      "documents_found": 3,
      "values_loaded": 3,
      "iterations": 4,
      "operators": [
        {
          "operator": "LuceneSourceOperator[shards = [data:0], maxPageSize = 21845, remainingDocs = 997]",
          "status": {
            "processed_slices": 1,
            "processed_queries": [
              "*:*"
            ],
            "processed_shards": [
              "data:0"
            ],
            "process_nanos": 7247187,
            "slice_index": 0,
            "total_slices": 1,
            "pages_emitted": 3,
            "slice_min": 0,
            "slice_max": 0,
            "current": 2147483647,
            "rows_emitted": 3,
            "partitioning_strategies": {
              "data:0": "SHARD",
              "data:2": "SHARD",
              "data:4": "SHARD"
            }
          }
        },
        {
          "operator": "ValuesSourceReaderOperator[fields = [language_code]]",
          "status": {
            "readers_built": {
              "language_code:column_at_a_time:BlockDocValuesReader.SingletonLongs": 3
            },
            "values_loaded": 3,
            "process_nanos": 7687185,
            "pages_processed": 3,
            "rows_received": 3,
            "rows_emitted": 3
          }
        },
        {
          "operator": "ProjectOperator[projection = [1]]",
          "status": {
            "process_nanos": 255762,
            "pages_processed": 3,
            "rows_received": 3,
            "rows_emitted": 3
          }
        },
        {
          "operator": "ExchangeSinkOperator",
          "status": {
            "pages_received": 3,
            "rows_received": 3
          }
        }
      ],
      "sleeps": {
        "counts": {},
        "first": [],
        "last": []
      }
    },
    {
      "description": "node_reduce",
      "cluster_name": "runTask",
      "node_name": "runTask-0",
      "start_millis": 1748954775825,
      "stop_millis": 1748954775848,
      "took_nanos": 23353559,
      "cpu_nanos": 1673141,
      "documents_found": 0,
      "values_loaded": 0,
      "iterations": 6,
      "operators": [
        {
          "operator": "ExchangeSourceOperator",
          "status": {
            "pages_waiting": 0,
            "pages_emitted": 3,
            "rows_emitted": 3
          }
        },
        {
          "operator": "ExchangeSinkOperator",
          "status": {
            "pages_received": 3,
            "rows_received": 3
          }
        }
      ],
      "sleeps": {
        "counts": {
          "exchange empty": 2
        },
        "first": [
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-0][esql_worker][T#4]",
            "sleep_millis": 1748954775825,
            "wake_millis": 1748954775840
          },
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-0][esql_worker][T#8]",
            "sleep_millis": 1748954775841,
            "wake_millis": 1748954775847
          }
        ],
        "last": [
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-0][esql_worker][T#4]",
            "sleep_millis": 1748954775825,
            "wake_millis": 1748954775840
          },
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-0][esql_worker][T#8]",
            "sleep_millis": 1748954775841,
            "wake_millis": 1748954775847
          }
        ]
      }
    },
    {
      "description": "data",
      "cluster_name": "runTask",
      "node_name": "runTask-1",
      "start_millis": 1748954775931,
      "stop_millis": 1748954775954,
      "took_nanos": 22578771,
      "cpu_nanos": 14544531,
      "documents_found": 1,
      "values_loaded": 1,
      "iterations": 2,
      "operators": [
        {
          "operator": "LuceneSourceOperator[shards = [data:1], maxPageSize = 21845, remainingDocs = 999]",
          "status": {
            "processed_slices": 1,
            "processed_queries": [
              "*:*"
            ],
            "processed_shards": [
              "data:1"
            ],
            "process_nanos": 6058149,
            "slice_index": 0,
            "total_slices": 2,
            "pages_emitted": 1,
            "slice_min": 0,
            "slice_max": 0,
            "current": 2147483647,
            "rows_emitted": 1,
            "partitioning_strategies": {
              "data:1": "SHARD",
              "data:3": "SHARD"
            }
          }
        },
        {
          "operator": "ValuesSourceReaderOperator[fields = [language_code]]",
          "status": {
            "readers_built": {
              "language_code:column_at_a_time:BlockDocValuesReader.SingletonLongs": 1
            },
            "values_loaded": 1,
            "process_nanos": 7290700,
            "pages_processed": 1,
            "rows_received": 1,
            "rows_emitted": 1
          }
        },
        {
          "operator": "ProjectOperator[projection = [1]]",
          "status": {
            "process_nanos": 141807,
            "pages_processed": 1,
            "rows_received": 1,
            "rows_emitted": 1
          }
        },
        {
          "operator": "ExchangeSinkOperator",
          "status": {
            "pages_received": 1,
            "rows_received": 1
          }
        }
      ],
      "sleeps": {
        "counts": {},
        "first": [],
        "last": []
      }
    },
    {
      "description": "data",
      "cluster_name": "runTask",
      "node_name": "runTask-1",
      "start_millis": 1748954775933,
      "stop_millis": 1748954775953,
      "took_nanos": 20241109,
      "cpu_nanos": 13834484,
      "documents_found": 1,
      "values_loaded": 1,
      "iterations": 2,
      "operators": [
        {
          "operator": "LuceneSourceOperator[shards = [data:3], maxPageSize = 21845, remainingDocs = 999]",
          "status": {
            "processed_slices": 1,
            "processed_queries": [
              "*:*"
            ],
            "processed_shards": [
              "data:3"
            ],
            "process_nanos": 6068188,
            "slice_index": 0,
            "total_slices": 2,
            "pages_emitted": 1,
            "slice_min": 0,
            "slice_max": 0,
            "current": 2147483647,
            "rows_emitted": 1,
            "partitioning_strategies": {
              "data:1": "SHARD",
              "data:3": "SHARD"
            }
          }
        },
        {
          "operator": "ValuesSourceReaderOperator[fields = [language_code]]",
          "status": {
            "readers_built": {
              "language_code:column_at_a_time:BlockDocValuesReader.SingletonLongs": 1
            },
            "values_loaded": 1,
            "process_nanos": 7290920,
            "pages_processed": 1,
            "rows_received": 1,
            "rows_emitted": 1
          }
        },
        {
          "operator": "ProjectOperator[projection = [1]]",
          "status": {
            "process_nanos": 141617,
            "pages_processed": 1,
            "rows_received": 1,
            "rows_emitted": 1
          }
        },
        {
          "operator": "ExchangeSinkOperator",
          "status": {
            "pages_received": 1,
            "rows_received": 1
          }
        }
      ],
      "sleeps": {
        "counts": {},
        "first": [],
        "last": []
      }
    },
    {
      "description": "node_reduce",
      "cluster_name": "runTask",
      "node_name": "runTask-1",
      "start_millis": 1748954775938,
      "stop_millis": 1748954775960,
      "took_nanos": 21089916,
      "cpu_nanos": 2135912,
      "documents_found": 0,
      "values_loaded": 0,
      "iterations": 6,
      "operators": [
        {
          "operator": "ExchangeSourceOperator",
          "status": {
            "pages_waiting": 0,
            "pages_emitted": 2,
            "rows_emitted": 2
          }
        },
        {
          "operator": "LimitOperator[limit = 998/1000]",
          "status": {
            "limit": 1000,
            "limit_remaining": 998,
            "pages_processed": 2,
            "rows_received": 2,
            "rows_emitted": 2
          }
        },
        {
          "operator": "ExchangeSinkOperator",
          "status": {
            "pages_received": 1,
            "rows_received": 2
          }
        }
      ],
      "sleeps": {
        "counts": {
          "exchange empty": 3
        },
        "first": [
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-1][esql_worker][T#4]",
            "sleep_millis": 1748954775940,
            "wake_millis": 1748954775954
          },
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-1][esql_worker][T#6]",
            "sleep_millis": 1748954775954,
            "wake_millis": 1748954775954
          },
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-1][esql_worker][T#8]",
            "sleep_millis": 1748954775954,
            "wake_millis": 1748954775958
          }
        ],
        "last": [
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-1][esql_worker][T#4]",
            "sleep_millis": 1748954775940,
            "wake_millis": 1748954775954
          },
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-1][esql_worker][T#6]",
            "sleep_millis": 1748954775954,
            "wake_millis": 1748954775954
          },
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-1][esql_worker][T#8]",
            "sleep_millis": 1748954775954,
            "wake_millis": 1748954775958
          }
        ]
      }
    },
    {
      "description": "final",
      "cluster_name": "runTask",
      "node_name": "runTask-0",
      "start_millis": 1748954775763,
      "stop_millis": 1748954775968,
      "took_nanos": 205001324,
      "cpu_nanos": 1016043,
      "documents_found": 0,
      "values_loaded": 0,
      "iterations": 9,
      "operators": [
        {
          "operator": "ExchangeSourceOperator",
          "status": {
            "pages_waiting": 0,
            "pages_emitted": 4,
            "rows_emitted": 5
          }
        },
        {
          "operator": "LimitOperator[limit = 995/1000]",
          "status": {
            "limit": 1000,
            "limit_remaining": 995,
            "pages_processed": 4,
            "rows_received": 5,
            "rows_emitted": 5
          }
        },
        {
          "operator": "OutputOperator[columns = [language_code]]"
        }
      ],
      "sleeps": {
        "counts": {
          "exchange empty": 4
        },
        "first": [
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-0][esql_worker][T#5]",
            "sleep_millis": 1748954775769,
            "wake_millis": 1748954775841
          },
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-0][esql_worker][T#6]",
            "sleep_millis": 1748954775841,
            "wake_millis": 1748954775841
          },
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-0][esql_worker][T#10]",
            "sleep_millis": 1748954775842,
            "wake_millis": 1748954775963
          },
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-0][esql_worker][T#11]",
            "sleep_millis": 1748954775963,
            "wake_millis": 1748954775968
          }
        ],
        "last": [
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-0][esql_worker][T#5]",
            "sleep_millis": 1748954775769,
            "wake_millis": 1748954775841
          },
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-0][esql_worker][T#6]",
            "sleep_millis": 1748954775841,
            "wake_millis": 1748954775841
          },
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-0][esql_worker][T#10]",
            "sleep_millis": 1748954775842,
            "wake_millis": 1748954775963
          },
          {
            "reason": "exchange empty",
            "thread_name": "elasticsearch[runTask-0][esql_worker][T#11]",
            "sleep_millis": 1748954775963,
            "wake_millis": 1748954775968
          }
        ]
      }
    }
  ],
  "plans": [
    {
      "description": "data",
      "cluster_name": "runTask",
      "node_name": "runTask-0",
      "plan_tree": "ExchangeSinkExec[[language_code{f}#2],false]\n\\_ProjectExec[[language_code{f}#2]]\n  \\_FieldExtractExec[language_code{f}#2]<[],[]>\n    \\_EsQueryExec[data], indexMode[standard], query[][_doc{f}#3], limit[1000], sort[] estimatedRowSize[12]"
    },
    {
      "description": "node_reduce",
      "cluster_name": "runTask",
      "node_name": "runTask-0",
      "plan_tree": "ExchangeSinkExec[[language_code{f}#2],false]\n\\_ExchangeSourceExec[[language_code{f}#2],false]"
    },
    {
      "description": "data",
      "cluster_name": "runTask",
      "node_name": "runTask-1",
      "plan_tree": "ExchangeSinkExec[[language_code{f}#1],false]\n\\_ProjectExec[[language_code{f}#1]]\n  \\_FieldExtractExec[language_code{f}#1]<[],[]>\n    \\_EsQueryExec[data], indexMode[standard], query[][_doc{f}#2], limit[1000], sort[] estimatedRowSize[12]"
    },
    {
      "description": "node_reduce",
      "cluster_name": "runTask",
      "node_name": "runTask-1",
      "plan_tree": "ExchangeSinkExec[[language_code{f}#1],false]\n\\_LimitExec[1000[INTEGER],8]\n  \\_ExchangeSourceExec[[language_code{f}#1],false]"
    },
    {
      "description": "final",
      "cluster_name": "runTask",
      "node_name": "runTask-0",
      "plan_tree": "OutputExec[org.elasticsearch.xpack.esql.plugin.ComputeService$$Lambda/0x000000000c464e08@35b2b181]\n\\_LimitExec[1000[INTEGER],8]\n  \\_ExchangeSourceExec[[language_code{f}#2],false]"
    }
  ]
}
}

@idegtiarenko idegtiarenko requested a review from nik9000 June 3, 2025 13:12
@idegtiarenko idegtiarenko added >non-issue Team:Analytics Meta label for analytical engine team (ESQL/Aggs/Geo) :Analytics/ES|QL AKA ESQL v9.1.0 labels Jun 3, 2025
return b;
}),
ChunkedToXContentHelper.array("drivers", profile.drivers.iterator(), params),
ChunkedToXContentHelper.array("plans", profile.plans.iterator()),
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This adds following section:

  "plans": [
    {
      "description": "data",
      "cluster_name": "runTask",
      "node_name": "runTask-0",
      "plan_tree": "ExchangeSinkExec[[language_code{f}#2],false]\n\\_ProjectExec[[language_code{f}#2]]\n  \\_FieldExtractExec[language_code{f}#2]<[],[]>\n    \\_EsQueryExec[data], indexMode[standard], query[][_doc{f}#3], limit[1000], sort[] estimatedRowSize[12]"
    },
    {
      "description": "node_reduce",
      "cluster_name": "runTask",
      "node_name": "runTask-0",
      "plan_tree": "ExchangeSinkExec[[language_code{f}#2],false]\n\\_ExchangeSourceExec[[language_code{f}#2],false]"
    },
    {
      "description": "data",
      "cluster_name": "runTask",
      "node_name": "runTask-1",
      "plan_tree": "ExchangeSinkExec[[language_code{f}#1],false]\n\\_ProjectExec[[language_code{f}#1]]\n  \\_FieldExtractExec[language_code{f}#1]<[],[]>\n    \\_EsQueryExec[data], indexMode[standard], query[][_doc{f}#2], limit[1000], sort[] estimatedRowSize[12]"
    },
    {
      "description": "node_reduce",
      "cluster_name": "runTask",
      "node_name": "runTask-1",
      "plan_tree": "ExchangeSinkExec[[language_code{f}#1],false]\n\\_LimitExec[1000[INTEGER],8]\n  \\_ExchangeSourceExec[[language_code{f}#1],false]"
    },
    {
      "description": "final",
      "cluster_name": "runTask",
      "node_name": "runTask-0",
      "plan_tree": "OutputExec[org.elasticsearch.xpack.esql.plugin.ComputeService$$Lambda/0x000000000c464e08@35b2b181]\n\\_LimitExec[1000[INTEGER],8]\n  \\_ExchangeSourceExec[[language_code{f}#2],false]"
    }
  ]

json is not particularly great when displaying multi-line strings. I wonder if there is any trick that could help us make tree a bit more readable? May be display array of lines instead of songle line with breaks?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd be fine with breaking on \n into an array. It's easier to read.

I'd also be fine keeping the big string. It's quite honest about what's really there.

I suppose the best thing would be to build some kind of object tree structure. The plan tree rendering code already does some of that - but it's optimized for string-y-ness. It'll, like, discard long stuff too. And we don't need that in this json response. At least, not for readability. It'd be bad to have a 40mb plan. But I don't think this is worth doing in this PR. It's a bunch more work and either the array of lines or the giant string is good.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The plan-tree is actually an ASCII-art rendering of a tree structure. We should instead export that tree as a JSON tree (with parent-child nesting). I was planning to do this based on feedback from the work I did for query plan visualization. Costin pointed out that there was precedence in the QL code-base for exporting to graphviz. We do not need to go and support graphviz, but leave something as specific as that to external tools. We should at least print the plan tree as JSON instead of ascii-art. This would be a good improvement.

# Conflicts:
#	server/src/main/java/org/elasticsearch/TransportVersions.java
# Conflicts:
#	server/src/main/java/org/elasticsearch/TransportVersions.java
@idegtiarenko idegtiarenko marked this pull request as ready for review June 4, 2025 09:44
@elasticsearchmachine
Copy link
Collaborator

Pinging @elastic/es-analytical-engine (Team:Analytics)

@nik9000 nik9000 added auto-backport Automatically create backport pull requests when merged v8.19.0 labels Jun 10, 2025
Copy link
Member

@nik9000 nik9000 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM.

Two important things to think about:

  1. I think you should backport this, even though it'll take a while. It'll be nice to have in 8.19 given how long it'll live.
  2. Does this appear in the task output? Can you add it? I think it'd be useful to have there.

If this is already in the task can you add something to EsqlActionTaskIT? If it's not in the task, I'm happy for you merge this as is and add to the task later if you have time. Or add it in this PR. Either is fine by me.

@@ -281,6 +281,7 @@ static TransportVersion def(int id) {
public static final TransportVersion IDP_CUSTOM_SAML_ATTRIBUTES = def(9_087_0_00);
public static final TransportVersion JOIN_ON_ALIASES = def(9_088_0_00);
public static final TransportVersion ILM_ADD_SKIP_SETTING = def(9_089_0_00);
public static final TransportVersion ESQL_PROFILE_INCLUDE_PLAN = def(9_090_0_00);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I had said to auto-backport this. but it needs a transport version change. I should have know it does.

I think it's still worth it. Imagine someone giving us an 8.19 profile a year from now - we'll be happy that you added the plan....

@@ -286,13 +287,19 @@ private Iterator<ToXContent> profileRenderer(ToXContent.Params params) {
if (profile == null) {
return Collections.emptyIterator();
}
return Iterators.concat(ChunkedToXContentHelper.startObject("profile"), ChunkedToXContentHelper.chunk((b, p) -> {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wonder if we should do like:

List<Iterator> all = new ArrayList<>();
all.add(ChunkedToXContentHelper.startObject("profile"));
if (executionInfo != null) {
  all.add(ChunkedToXContentHelper.chunk((b, p) -> b.field("query", executionInfo.overallTimeSpan()),field("planning", executionInfo.planningTimeSpan());
}
...

That keeps everything on one line nicely and means expansions don't make big changes to the layout. And the ArrayList isn't a big allocation - just a bunch of pointers in it.

return b;
}),
ChunkedToXContentHelper.array("drivers", profile.drivers.iterator(), params),
ChunkedToXContentHelper.array("plans", profile.plans.iterator()),
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd be fine with breaking on \n into an array. It's easier to read.

I'd also be fine keeping the big string. It's quite honest about what's really there.

I suppose the best thing would be to build some kind of object tree structure. The plan tree rendering code already does some of that - but it's optimized for string-y-ness. It'll, like, discard long stuff too. And we don't need that in this json response. At least, not for readability. It'd be bad to have a 40mb plan. But I don't think this is worth doing in this PR. It's a bunch more work and either the array of lines or the giant string is good.

# Conflicts:
#	server/src/main/java/org/elasticsearch/TransportVersions.java
#	x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlQueryResponse.java
@idegtiarenko idegtiarenko merged commit 56d5009 into elastic:main Jun 25, 2025
33 checks passed
@idegtiarenko idegtiarenko deleted the profile_with_plan branch June 25, 2025 08:50
@elasticsearchmachine
Copy link
Collaborator

💔 Backport failed

Status Branch Result
8.19 Commit could not be cherrypicked due to conflicts

You can use sqren/backport to manually backport by running backport --upstream elastic/elasticsearch --pr 128828

@idegtiarenko
Copy link
Contributor Author

Backport depends on #125631

@nik9000
Copy link
Member

nik9000 commented Jun 26, 2025

Backport depends on #125631

Done.

idegtiarenko added a commit to idegtiarenko/elasticsearch that referenced this pull request Jun 27, 2025
idegtiarenko added a commit to idegtiarenko/elasticsearch that referenced this pull request Jun 27, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
:Analytics/ES|QL AKA ESQL auto-backport Automatically create backport pull requests when merged >non-issue Team:Analytics Meta label for analytical engine team (ESQL/Aggs/Geo) v8.19.0 v9.1.0
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants