[Search] Async search backing off strategy makes dashboards slow when searches take less than 1s to be served

[dej611]

Describe the bug:

While debugging a slow dashboard I've realised that most of the waiting time was due to the async search backing off polling strategy.
Each ES search query time was within 1s, many around 500ms, but often the first request was served back from the server within 150ms: this triggered the first 1000ms delay for a new polling request, so the final Kibana reported time is can be even more than 2x the ES response timing.

In this example the final timing is the sum of the 2 requests + the 1s delay, taking more than 1.5s while ES reports less than 300ms to serve the full respose:

1684224058942 - 1684224058484 = 458ms (ES time 105ms) // Initial async search
1684224060231 - 1684224059958 = 273ms (ES time 247ms) // second polling request

458 + 273 + 1000 = 1731ms // <= the final reported time

Maybe we could improve this aspect of the polling strategy?
One idea could be providing an additional step for the initial polling delay of 500ms for the first second?
On the other hand, discussing with @martijnvg offline, ES could take a little bit longer (from 100ms to ~200ms) to serve the first request in order to catch all "faster" searches and reduce the polling for these. Perhaps the two could be adopted together in some form?

cc @ppisljar @lukasolson

[elasticmachine]

Pinging @elastic/kibana-visualizations @elastic/kibana-visualizations-external (Team:Visualizations)

[elasticmachine]

Pinging @elastic/kibana-data-discovery (Team:DataDiscovery)

[henrikno]

Rel: #143277

[dej611]

Had a go with an investigation on this, but couldn't find a the real offender of the performance problem.
First of all a diagram of the architecture in place:

flowchart TB
  SearchInterceptor[Search Interceptor w/ Polling] --"Network Request"--> bFetch.onBatchItem
  subgraph CLIENT
    subgraph DATA PLUGIN
      SearchInterceptor[Search Interceptor w/ Polling]
    end
    Expression --> SearchInterceptor
    subgraph DASHBOARD
      subgraph EMBEDDABLE
        subgraph LENS
            Chart --> Expression
        end
      end
    end
  end
  ESESearch --"Network Request"--> Elasticsearch
  subgraph KIBANA [SERVER KIBANA]
    subgraph DATA PLUGIN
      bFetch.onBatchItem --> ESESearch[ESE Search Strategy w/ Polling]
      ESESearch <--> UiSettings
    end
  end
  subgraph ES [SERVER ES]
    Elasticsearch
  end

Loading

While at the beginning I thought uiSettingsClient was a bottleneck I've found that it was not the case as long as get calls happen not concurrently (not await Promise.all([ .... ])) as there's a caching wrapper around the client which leverages the fact that get calls are in series.
The Observable structure makes a bit hard to debug/profile the exact timings and order of each function as there's a lot of noise in the profile stacktrace.

It was still not clear to me where most of the time is lost. Measuring timings from both Kibana client and server side it looks like at least a 1s overhead is spent somewhere else than the actual request handling, and I assume the network delay in that case to be minimal as both were running locally (the ES cluster was remote to simulate a slow request).
So perhaps more investigation is due here to better understand where the actual time is spent.

[lukasolson]

Would this be solved by increasing the wait_for_completion_timeout to something like 1s?