ES|QL - Add parsing, preanalysis and analysis timing information to profile

[carlosdelest]

Adds parsing, preanalysis and analysis timing information to the profile output:

{
    "profile": {
        "query": {
            "start_millis": 1765995832363,
            "stop_millis": 1765995832370,
            "took_millis": 7,
            "took_nanos": 7435667
        },
        "planning": {
            "start_millis": 1765995832363,
            "stop_millis": 1765995832366,
            "took_millis": 3,
            "took_nanos": 2865708
        },
        "parsing": {
            "start_millis": 1765995832363,
            "stop_millis": 1765995832364,
            "took_millis": 1,
            "took_nanos": 750125
        },
        "preanalysis": {
            "start_millis": 1765995832364,
            "stop_millis": 1765995832364,
            "took_millis": 0,
            "took_nanos": 31791
        },
        "dependency_resolution": {
            "start_millis": 1765995832364,
            "stop_millis": 1765995832365,
            "took_millis": 1,
            "took_nanos": 1165791
        },
        "analysis": {
            "start_millis": 1765995832365,
            "stop_millis": 1765995832365,
            "took_millis": 0,
            "took_nanos": 403458
        }
}

dependency_resolution include a number of operations related to dependency resolution:

• Retrieving field caps information
• Resolve enrich policies
• Resolve inference IDs

This helps understanding the amount of time ES|QL spends doing non planning operations, including specifically field_caps checks.

[elasticsearchmachine]

Hi @carlosdelest, I've created a changelog YAML for you.

[elasticsearchmachine]

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

[idegtiarenko]

I'd like to suggest we split preanalysis into preanalysis as above and dependency-resolution (as FC calls) as it becoming a significant dependency for us.

[carlosdelest]

Done!

[idegtiarenko]

EsqlExecutionInfo has grown to almost 800 lines and has multiple responsibilities now (such as ccs info tracking, profiling, status reportin, isPartial, isStopped). Currently we are thinking about a ways to manage that.

I wonder if that would make sense to group all transient timers and define them in a new private final transient PlanningProfile field? This would allow to move some of this class complexity elsewhere.

[carlosdelest]

Makes sense - I've created a PlanningProfile class and moved planning related profiling there.

[idegtiarenko]

All of the markBegin** and markEnd** do the same things: verify the state and perform the action.
I wonder if we could introduce a component with Builder and Span that verifies those state transition.
I imagine something like:

class TimeSpanRecorder {
    private TimeSpan.Builder builder;
    private TimeSpan span;

    public void start() {/*assert  is called first time and start a builder*/}
    public void stop() {/*assert is called first time and create a span*/}
    public TimeSpan get() {..}   
}

All usages could be simplified to:

executionInfo.planningProfile().analysis().start();
...
executionInfo.planningProfile().analysis().stop();

[idegtiarenko]

I believe dependencyResolutionMarker and analysisMarker are having allowMultipleCalls=true because of the possible analysis retry. I wonder if in this case we should sum the the duration instead of discarding the first attempt? The query is getting longer because of extra attempts.

Possibly we want to record the fact of retrying and total FieldCaps call count as well, but I believe this is out of scope of this change.

[carlosdelest]

I believe dependencyResolutionMarker and analysisMarker are having allowMultipleCalls=true because of the possible analysis retry.

Correct

I wonder if in this case we should sum the the duration instead of discarding the first attempt?

We're doing that - in case start() is invoked again when multiple invocations are allowed, we keep the original starting time.

We could count etc but let's get this change in and we can refine later if needed - at the very least we will get a longer time in dependency resolution / analysis that will hint about having multiple retriees.

[idegtiarenko]

We're doing that - in case start() is invoked again when multiple invocations are allowed, we keep the original starting time.

I am not sure this is correct:

maker1.start();
maker1.stop();
...
maker2.start();
maker2.stop();
...
maker1.start();
maker1.stop();

This way the maker1 would keep the entire duration from first start to the last stop call, not the combined duration of first and second intervals.

This PR is a big improvement on its own, I do not mind changing repeated start/stop behavior later.

[carlosdelest]

I see your point - I was thinking on total duration, not in summing up the individual steps.

Yep, let's refine that behavior later 👍

[idegtiarenko]

Left one suggestion regarding summing duration in case of retries.

Overall, looks good, thanks for the contribution!