Skip to content

[FEATURE] Optimization phase caching #5645

Description

@Swiddis

Is your feature request related to a problem?
Optimization takes non-negligible time. This is usually buried under the profile endpoint, but since we've introduced @Krish-Gandhi's analyze feature, it's a lot more readily visible while analyzing queries. The step has high variance, and can take anywhere from 5 ms to 70 ms.

I've assembled a query set of both simple and complex queries (as defined in #5628): 27 simple and 25 complex. I ran a benchmark over the set with 93,165 executions over 1 hour, with index caching enabled.

The dataset is about 1 GB in size (1 mil. records) which means execution phase timings are relatively reduced (particularly for complex queries), but the expectation is that caching should usually apply and I have seen this general shape with production-scale datasets.

Looking at the profiles during this run:

Image

Key takeaways:

  • Optimization is significantly more significant for simple queries than complex queries. Complex queries have bad result caching behavior due to minor cross-run differences in our script codegen. We can prioritize improvements on simple queries.
  • For simple queries, optimization is comparable with execution time (almost the same). There are 9 queries where the optimization time is more than the execution time on average.

What solution would you like?

One way to reduce optimization time in this scenario is to consider caching the query optimization stage, either from the parsed logical plan directly, or on the query text. This would be highly applicable to scenarios like OSD's dashboards & visualizations, which may be repeatedly run or refreshed by multiple users in short timespans during events. Doing it by query text directly is tricky, due to functions like now().

If we can somehow intelligently optimize based on parts of the shape of the logical plan, we also have the potential to reuse shared parts of queries.

This is useful, for example, if the same dashboard query is being run repeatedly with different time filters (where the only meaningful query difference is the time range, which is irrelevant to the optimizer).

A more complex case: it might also could be useful in cases where the same base query is being run with multiple tails, as in the typical case of someone iteratively writing a query in the Explore frontend. They may start with a query like source=... | a | b | c and in short succession run things like ... | c | d, ... | c | e. I expect this to be less impactful overall than mere time-invariant caching would be.

What alternatives have you considered?

Make optimization itself faster. I haven't looked much into what opportunities exist here, I know historically the majority of our optimization time has been in the volcano stage. Most likely the primary candidate to look at would be our pushdown rules and how they affect volcano passes.

Do you have any additional context?

For completeness, here's the top 5 queries with the most relative optimization time.

source=logs
| where latency_ms > 2000
| stats count() as slow_requests, avg(latency_ms) as avg_lat by http_method, endpoint_path
| where slow_requests > 10
| sort - slow_requests
source=logs
| where is_error = 1
| stats
    count() as errors,
    avg(latency_ms) as avg_latency,
    avg(retry_count) as avg_retries
    by status_code, status_text, service_name
| eval severity = case(
    status_code >= 500, 'critical',
    status_code = 429, 'warning',
    status_code >= 400, 'info'
)
| sort - errors
source=logs
| where is_timeout = 1
| stats
    count() as timeouts,
    avg(latency_ms) as avg_timeout_ms,
    avg(upstream_latency_ms) as avg_upstream_ms
    by service_name, status_code
| sort - timeouts
source=logs
| where retry_count > 0
| stats
    count() as retried_requests,
    avg(retry_count) as avg_retries,
    sum(is_error) as still_failed
    by service_name, status_code
| eval success_after_retry = retried_requests - still_failed
| eval retry_success_rate = round(100.0 * success_after_retry / retried_requests, 2)
| sort - retried_requests
source=logs
| where is_error = 1
| rex field=raw_log "\" (?<status>\d{3}) " max_match=1
| eval status_class = IF(status >= '500', '5xx', IF(status >= '400', '4xx', 'other'))
| stats count() as total, sum(is_timeout) as timeouts
| eval timeout_rate = timeouts * 100.0 / total

Unrelated: Apparently about 20% of execution time of simple queries is unaccounted for in our profile endpoint? I wonder where that's going.

Metadata

Metadata

Assignees

No one assigned

    Labels

    PPLPiped processing languagecalcitecalcite migration releatedenhancementNew feature or requestperformanceMake it fast!untriaged

    Type

    No type

    Projects

    Status
    Not Started

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions