Diagnosing Elasticsearch Search Latency: Profile API to Caches

A slow Elasticsearch search is slow in one specific place: the coordinating node fanning out to too many shards, one shard taking far longer than its peers, the query phase scoring too many documents, the fetch phase loading large documents, or the request waiting in a thread pool queue before it runs at all. The took value in the response hides which. The answer is to decompose the latency before changing anything: compare query and fetch time from node stats, catch real slow requests with the search slow log, take one apart with the profile API, check whether the caches that should help are actually hitting, and then fix the pattern responsible, which is usually one of a short list (leading wildcards, scripts, deep pagination, exact total hit counts, high-cardinality aggregations, numeric IDs queried as terms). This article covers the execution model, each tool, and the patterns.

The mental model: how a search executes

A search request goes through these steps:

1. The coordinating node receives the request. Any node can coordinate. It resolves the target indices, aliases and data streams into a list of shards, and picks one copy (primary or replica) of each.
2. The can_match (pre-filter) phase, when it runs, asks each shard cheaply whether it could possibly match: for example, whether a range filter on @timestamp overlaps the shard's minimum and maximum values. Shards that cannot match are skipped.
3. The query phase. Each selected shard executes the query against its segments, scores matching documents, collects the top from + size hits (document IDs and sort values only) and computes its part of any aggregations. It returns these to the coordinating node.
4. The reduce. The coordinating node merges the per-shard top hits into a global top size and reduces the aggregations. With many shards, this is done in batches as results arrive.
5. The fetch phase. The coordinating node asks only the shards that hold the final top hits for those documents: _source, stored fields, highlighting, fields and doc value fields.
6. The response returns with took (total milliseconds measured on the coordinating node), timed_out, and the _shards counts.

Two properties of this model drive almost every diagnosis:

• The query phase is as slow as the slowest shard copy it waits for. A search over 50 shards waits for all 50. One slow node, one oversized shard or one shard in a long GC pause sets the latency for every request that touches it.
• The fetch phase scales with size and document size, not with how many documents matched. A query that matches 100 million documents but returns 10 small ones has a cheap fetch. A query that returns 1,000 large documents with highlighting has an expensive one.

The shard-level work runs on the node's search thread pool, a fixed pool of int((allocated processors x 3) / 2) + 1 threads with a queue of 1000. When searches arrive faster than shards complete, they wait in that queue, and the wait counts in took but in no shard's profile.

Step 1: split query time from fetch time

Node-level search stats separate the two phases, cumulative since node start:

GET _nodes/stats/indices/search?filter_path=nodes.*.name,nodes.*.indices.search

{
  "nodes": {
    "x9": {
      "name": "es-hot-02",
      "indices": {
        "search": {
          "query_total": 482113002,
          "query_time_in_millis": 1923004113,
          "query_current": 31,
          "fetch_total": 401238770,
          "fetch_time_in_millis": 288110345,
          "fetch_current": 2
        }
      }
    }
  }
}

These counters are per shard-level operation, not per user request: a search over 20 shards adds 20 to query_total. Take two samples a minute apart and compute, per node:

average query ms per shard = delta(query_time_in_millis) / delta(query_total)
average fetch ms per shard = delta(fetch_time_in_millis) / delta(fetch_total)

Worked example. Over 60 seconds a node's query_total rises by 120,000 and query_time_in_millis by 4,800,000. That is 40 ms per shard query. Its fetch_total rises by 90,000 and fetch_time_in_millis by 450,000, which is 5 ms per fetch. Query dominates: look at the queries and aggregations, not at document size. If another node in the same tier shows 160 ms per shard query for the same workload, the problem is that node (hardware, a hot shard, GC), not the query.

Compare query_current across nodes too. A node with far more in-flight shard queries than its peers is receiving more of the load or completing it more slowly.

Check the queue at the same time:

GET _cat/thread_pool/search?v&h=node_name,name,active,queue,rejected,completed

A non-zero, growing queue means requests wait before they run. That wait is invisible to the profile API.

Step 2: catch the slow requests with the search slow log

Node stats give averages. The slow log gives you the actual requests. It is configured per index, separately for the query and fetch phases, with four levels, and is disabled by default (every threshold is -1):

PUT logs-app-*/_settings
{
  "index.search.slowlog.threshold.query.warn": "5s",
  "index.search.slowlog.threshold.query.info": "2s",
  "index.search.slowlog.threshold.query.debug": "500ms",
  "index.search.slowlog.threshold.fetch.warn": "1s",
  "index.search.slowlog.threshold.fetch.info": "500ms"
}

Three things about the slow log are easy to misread:

• It records shard-level execution time, on the node that ran the shard. A request whose total took is 4 seconds because it touched 200 shards at 100 ms each will not appear at a 1 second threshold. The slow log finds slow shards, not slow fan-out.
• The entry includes the full query source, so it is how you find which dashboard or application issued the request. Recent versions can also include the user that ran it, with index.search.slowlog.include.user.
• Thresholds are per index. Put them in your index templates so new indices inherit them. A common rule of thumb is to start with warn levels that would page no one but would show anomalies, then tighten them.

By default the entries are written to a dedicated search slow log file in the node's logs directory, in JSON format. Ship it with the rest of your logs; a slow log nobody reads is just disk usage.

Step 3: take one request apart with the profile API

Once you have a slow query, add "profile": true and run it:

GET logs-app-*/_search
{
  "profile": true,
  "size": 10,
  "query": {
    "bool": {
      "filter": [
        { "range": { "@timestamp": { "gte": "now-24h" } } },
        { "term": { "service": "checkout" } }
      ],
      "must": [
        { "wildcard": { "message": { "value": "*timeout*" } } }
      ]
    }
  }
}

The response gains a profile section with one entry per shard. Within each, the query tree is broken down:

{
  "profile": {
    "shards": [
      {
        "id": "[q1w2e3][logs-app-2026.10.21][0]",
        "searches": [
          {
            "query": [
              {
                "type": "BooleanQuery",
                "description": "#@timestamp:[1760950000000 TO 9223372036854775807] #service:checkout +message:*timeout*",
                "time_in_nanos": 2311343469,
                "breakdown": {
                  "create_weight": 140223112,
                  "build_scorer": 2104339011,
                  "next_doc": 51229004,
                  "advance": 9112330,
                  "score": 6440012,
                  "match": 0
                },
                "children": [
                  { "type": "MultiTermQueryConstantScoreWrapper", "description": "message:*timeout*", "time_in_nanos": 2201110433 }
                ]
              }
            ],
            "rewrite_time": 1882004,
            "collector": [
              { "name": "QueryPhaseCollector", "reason": "search_query_phase", "time_in_nanos": 61223001 }
            ]
          }
        ],
        "aggregations": []
      }
    ]
  }
}

How to read it:

• time_in_nanos per node in the query tree shows which clause costs the time. Here the wildcard clause accounts for nearly all of it.
• create_weight or build_scorer dominating points to expensive query setup, typical of multi-term queries (wildcard, prefix, regexp, fuzzy) that must enumerate matching terms in the term dictionary before matching any document.
• next_doc and advance dominating means iterating many matching documents; the query is simply broad.
• score dominating means scoring many documents; moving clauses that do not need scoring into filter context helps.
• collector time covers collecting top hits, and is high for large size or complex sorts. Collector and query class names differ between versions, so read the structure and the timings rather than matching names.
• The aggregations section profiles each aggregation separately, with its own timing breakdown.
• Recent versions also include a fetch section, which breaks down fetch-phase work such as loading stored fields and highlighting.

What the profile does not measure: network transfer, time queued in the thread pool, and the coordinating node's merging of shard responses (including the reduce phase of aggregations). If profile times are small and took is large, the time is in those places: fan-out across many shards, queueing, or a slow reduce of large aggregations.

Profiling adds overhead, so its absolute times are higher than normal execution. Use it to compare clauses within one request, not as a latency measurement. Kibana's Search Profiler, in Dev Tools, renders the same output as a tree, which is easier to read for large queries.

Step 4: check the caches

Three caches affect search latency, and each one caches something different.

Node query cache

Lucene does not cache every filter. It tracks how often each filter is used and caches only those that recur, and it skips very small segments where caching is not worth it. A filter that changes with every request (a range with an unrounded now, for example) is never reused, so it is never cached.

This is why Elastic's tuning guidance recommends rounding dates in queries that use now. "gte": "now-15m" is a different query every millisecond. "gte": "now-15m/m" is the same query for a whole minute and can be cached.

GET _nodes/stats/indices/query_cache?filter_path=nodes.*.name,nodes.*.indices.query_cache

Look at hit_count, miss_count, cache_size and evictions. A very low hit ratio with a cache at its size limit and high evictions means the cache is churning; usually the filters are not repeatable, and a bigger cache would not help.

Shard request cache

The shard request cache stores the entire shard-level result of a request. By default only requests with size: 0 are cached, which covers most dashboard aggregations. The cache key is the request body, so two requests that are logically identical but have JSON keys in a different order are different cache entries. It is invalidated whenever the shard refreshes with new data, which is why it is most valuable on indices that are no longer being written (yesterday's logs, older backing indices of a data stream) and close to useless on the write index of a busy data stream.

You can force caching on or off per request:

GET logs-app-*/_search?request_cache=true
{
  "size": 0,
  "aggs": {
    "by_service": { "terms": { "field": "service" } }
  }
}

GET _nodes/stats/indices/request_cache?filter_path=nodes.*.name,nodes.*.indices.request_cache

The same fields apply: hits, misses, memory size and evictions.

Fielddata and global ordinals

Aggregations and sorts on keyword fields use doc values and, for terms aggregations, global ordinals. Global ordinals are built lazily on the first such search after a refresh, which shows up as a periodic slow search on busy indices. eager_global_ordinals: true on the field moves that cost to refresh time; it suits fields that are aggregated on constantly. Fielddata on text fields is a heap problem first and a latency problem second; see JVM heap and circuit breakers.

Shard selection: pre-filter, concurrency and replica choice

pre_filter_shard_size

The can_match phase is a cheap round trip that can skip shards entirely. It is controlled by pre_filter_shard_size on the search request. If you do not set it, Elasticsearch runs the pre-filter when any of these is true: the request targets more than 128 shards; it targets one or more read-only indices; or the primary sort of the query is on an indexed field.

For time-series data this matters a great deal: a query over the last hour, against a data stream with 90 days of backing indices, can skip almost every shard if the pre-filter runs. Setting pre_filter_shard_size lower forces the pre-filter for requests with fewer shards, which can help when many of the targeted shards cannot match.

max_concurrent_shard_requests

The coordinating node limits how many shard requests it sends at once per node, with max_concurrent_shard_requests (default 5). This protects the cluster from one large request occupying every search thread. Raising it on a single request makes that request faster and every other request slower.

Adaptive replica selection

With cluster.routing.use_adaptive_replica_selection (default true), the coordinating node chooses among the copies of each shard based on recent response times, queue sizes and service times of the nodes holding them, instead of round-robin. It routes around a slow node automatically, which is one reason a single bad node causes less damage than it used to. It only helps if there are replicas to choose from: a shard with zero replicas has one copy, and every search touching it waits for that copy.

preference

The preference parameter routes requests with the same preference string to the same shard copies. Using a user or session ID as the preference keeps a user's requests on the same copies, which improves cache hit rates and makes paging through results consistent, at the cost of less even load spreading.

The slowest common query patterns

If you want to stop the worst of these at the door, search.allow_expensive_queries (default true) can be set to false. That makes the cluster reject a defined class of expensive queries, including script queries, fuzzy, regexp, wildcard and prefix queries (except where the field is indexed to support them), and joining queries. It is a blunt instrument: test it against every application first.

Timeouts and cancellation

A search without a timeout runs until it finishes. search.default_search_timeout defaults to -1, meaning no timeout. A request can set "timeout": "2s"; shards that exceed it return partial results and the response sets timed_out: true. Clients must check that flag, or they will present partial results as complete.

Running searches are tasks and can be listed and cancelled:

GET _tasks?actions=*search*&detailed=true

POST _tasks/<task_id>/_cancel

In recent versions, a search is also cancelled when the client closes its HTTP connection, so a client-side timeout that drops the connection stops the work on the cluster too.

Runbook: searches are slow

1. Scope it. Is it every search or one dashboard? Every index or one? One node or all? took from a few representative requests and the application's own latency metrics answer this.

2. Check queues and rejections.

   http GET _cat/thread_pool/search?v&h=node_name,name,active,queue,rejected&s=queue:desc

   Queueing on all nodes means capacity or a flood of expensive requests. Queueing on one node means that node.

3. Split query from fetch per node with two samples of _nodes/stats/indices/search. Compare nodes in the same tier.

4. Look at what is running now.

   http GET _tasks?actions=*search*&detailed=true&group_by=parents

   Long-running tasks show their request descriptions. Cancel a runaway if it is starving everything else.

5. Check the slow node.

   http GET _nodes/es-hot-02/hot_threads

   GC, merges or a specific query type in the stack traces point the way. Check heap and disk on that node too.

6. Enable or read the slow log on the affected indices to capture concrete slow requests.

7. Profile one of them and identify the expensive clause, aggregation or fetch step.
8. Check cache hit ratios for the node query cache and the shard request cache. Round now in date filters; aim dashboards at indices that are no longer being written where possible.
9. Fix the pattern, using the table above, and re-run the profile to confirm the clause cost dropped.

Key takeaways

• A search waits for the slowest shard copy it touches; one bad node or oversized shard sets latency for everyone.
• Split query time from fetch time with node stats before tuning anything; they have different causes and different fixes.
• The slow log finds slow shards, not slow fan-out. The profile API finds the slow clause, but not queueing, network or reduce time.
• Round now in filters so the node query cache can reuse them. The shard request cache helps size: 0 requests on indices that are no longer changing.
• The pre-filter phase, adaptive replica selection and replicas let the cluster skip shards and avoid slow nodes; zero-replica indices lose the second benefit.
• Most slow searches come from a short list of patterns: leading wildcards, scripts, deep pagination, exact total hit counts, large aggregations and numeric IDs.

How Sparced helps

Sparced reads node stats and thread pools for every node in one pass, so search queue depth and rejections appear per node alongside the shard layout, which is often where a single slow node or an uneven shard spread first shows itself. Each finding names the nodes and shards involved, shows the values it read, and gives a command to investigate and a check to confirm the fix. It does not run the profile API on your queries, enable slow logs, or guess which application issued a slow request; it installs no agent and writes nothing to the cluster.