Profile API, Explain, Search Slow Logs, Hot Threads, Tasks, and Distinguishing Query from Fetch Cost

Learning outcomes

AtlasMart receives a complaint: “category pages sometimes take two seconds.” One operator opens Profile, another reads slow logs, another checks hot threads, and a fourth lists tasks. All are valid tools, but each sees a different slice of reality. The goal is to join those slices into one causal timeline rather than argue over whichever metric looks dramatic.

1. Profile: execution detail with deliberate overhead

The Profile API instruments search components and returns per-shard operator/collector timing trees. It is ideal for answering questions such as “did the wildcard expansion dominate?”, “which aggregation consumed most query-phase time?”, or “did a filter rewrite into something cheaper?” It is intentionally intrusive and adds overhead.

Both products document important omissions. Profile is not the client clock: network latency, queue residence and coordinating-node idle/merge time are not fully represented. OpenSearch explicitly notes these omissions; Elastic likewise warns that Profile does not cover all search overhead. Therefore profile numbers must be paired with a normal, unprofiled latency distribution.

GET atlasmart-search-exec-v1/_search
{
  "profile": true,
  "size": 20,
  "query": {
    "bool": {
      "must": [{"match":{"name":"wireless headset"}}],
      "filter": [{"term":{"available":true}}]
    }
  },
  "aggs": {
    "categories": {"terms":{"field":"category","size":10}}
  }
}

• Inspect per-shard query tree descriptions and time breakdowns.
• Inspect collector/aggregation timings separately from hit fetch behavior.
• Repeat without profile:true for performance measurement; do not compare profiled request latency to an unprofiled baseline as if instrumentation were free.

2. Explain: why one document scored that way

_explain answers a relevance question for a specific document and query. It decomposes scoring contributions such as BM25 term frequency, document frequency, field length and boosts. It does not tell you whether the whole search is resource-efficient, and a deep explanation tree is not a benchmark.

Use it after Chapter 07’s relevance regression identifies a suspicious document. Keep a small number of representative documents; explaining thousands of hits is diagnostic abuse.

GET atlasmart-search-exec-v1/_explain/P-1000
{
  "query": {"match":{"name":"wireless headset"}}
}

3. Slow logs: historical shard evidence, not client latency

Elasticsearch search slow logs are shard-level and have separate query and fetch thresholds. Current Elastic documentation also recommends its newer query logging when end-to-end Elasticsearch request duration is the desired search signal. OpenSearch retains shard slow logs and, since 2.12, also has request-level search slow logs with phase timing such as query and fetch in the emitted entry.

Enable aggressive thresholds only in a disposable lab. Low thresholds can create substantial logging I/O and distort the workload being diagnosed.

PUT atlasmart-search-exec-v1/_settings
{
  "index.search.slowlog.threshold.query.warn":"50ms",
  "index.search.slowlog.threshold.fetch.warn":"50ms"
}

# Restore after the experiment:
PUT atlasmart-search-exec-v1/_settings
{
  "index.search.slowlog.threshold.query.warn":"-1",
  "index.search.slowlog.threshold.fetch.warn":"-1"
}

4. Hot threads and tasks: “what is running now?”

Hot threads samples threads spending CPU, blocking or waiting. It is a snapshot, so one sample can miss intermittent work. The Tasks API shows cancellable/running operations and is better for long-lived operations. Neither tool replaces application tracing because client retries and upstream queueing may happen before Elasticsearch/OpenSearch sees the request.

GET _nodes/hot_threads?threads=5&ignore_idle_threads=true
GET _tasks?detailed=true&actions=*search*
GET _nodes/stats/thread_pool,jvm,process,breaker?human
GET atlasmart-search-exec-v1/_stats/search?human

5. Controlled diagnosis workflow

1. Capture the exact request, target, routing/preference, client timeout and timestamp.
2. Measure an unprofiled latency distribution and response bytes.
3. Inspect _shards, failures/skips and task/thread-pool state during the event.
4. Enable temporary slow logging only if needed and with a narrow threshold/window.
5. Profile a bounded reproduction, not the entire production traffic stream.
6. If ranking is questioned, explain only representative documents.
7. Change one causal variable and rerun the same workload.

6. Lab: query-bound versus fetch-bound

PUT atlasmart-search-exec-v1
{
  "settings": {
    "number_of_shards": 3,
    "number_of_replicas": 0,
    "index.max_result_window": 100
  },
  "mappings": {
    "properties": {
      "sku":        {"type":"keyword"},
      "name":       {"type":"text","fields":{"raw":{"type":"keyword"}}},
      "category":   {"type":"keyword"},
      "price":      {"type":"double"},
      "available":  {"type":"boolean"},
      "updated_at": {"type":"date"},
      "popularity": {"type":"integer"}
    }
  }
}

# Save as chapter16_fixture.py and redirect stdout to fixture.ndjson.
import json
from datetime import datetime, timedelta, timezone
base = datetime(2026, 9, 1, tzinfo=timezone.utc)
for i in range(240):
    sku = f"P-{1000+i:04d}"
    meta = {"index":{"_index":"atlasmart-search-exec-v1","_id":sku}}
    doc = {
      "sku": sku,
      "name": f"AtlasMart {'wireless' if i%3==0 else 'wired'} headset model {i:03d}",
      "category": ["audio","mobile","office"][i%3],
      "price": round(20 + (i%80)*1.25, 2),
      "available": i%5 != 0,
      "updated_at": (base + timedelta(minutes=i)).isoformat().replace('+00:00','Z'),
      "popularity": (i*17)%101
    }
    print(json.dumps(meta,separators=(',',':')))
    print(json.dumps(doc,separators=(',',':')))
# Then POST fixture.ndjson to /_bulk?refresh=true with Content-Type application/x-ndjson.

GET atlasmart-search-exec-v1/_search
{
  "size":50,
  "_source":["sku"],
  "query":{"match_all":{}}
}

GET atlasmart-search-exec-v1/_search
{
  "size":50,
  "_source":true,
  "query":{"match_all":{}}
}

The synthetic fixture has small sources, so the latency delta may be tiny. That is acceptable. The lab objective is to prove the diagnostic method, not invent a fetch bottleneck. If you want a fetch-heavy reproduction, add a deterministic description payload to a disposable copy and disclose the payload size.

7. Production judgment

Observability tools answer different questions: client timing measures user experience; slow logs preserve historical server-side evidence; profile explains internal query execution; explain decomposes one score; hot threads samples runtime hotspots; tasks expose active operations. The reliable diagnosis is the intersection of these signals.

Never promote a profiled query directly to “X milliseconds in production.” Profile overhead, cache warmness, concurrency, shard placement, storage state and coordinator/network effects all change the end-to-end request.

Summary and next step

You now have an evidence hierarchy for slow search. Lesson 3 applies it to the most common correctness/performance pagination failure: deep from/size without a stable point-in-time view.

Authoritative references

• Elastic search API — Current search request options, search type, pre-filter shard behavior and partial-results controls.
• Elastic search profiling — Profile operator trees, collectors and DFS profiling; also documents what profile does not measure.
• Elastic pagination — from/size result window, search_after, PIT consistency and PIT cleanup guidance.
• Elastic point in time API — Opening PITs, keep_alive, changing PIT IDs and retained-segment resource implications.
• Elastic async search submit — Long-running asynchronous search submission and response-size constraints.
• Elastic async search results — Polling, ownership/security and keep_alive behavior for async search.
• Elastic slow logs — Shard-level query/fetch slow logs and current query-logging guidance.
• OpenSearch pagination — from/size, search_after and PIT-backed pagination tradeoffs.
• OpenSearch PIT — Create/list/delete PIT APIs, security permissions and resource lifetime.
• OpenSearch profile API — Search component timings and explicit omissions such as network/queue/coordinator idle time.
• OpenSearch asynchronous search — Plugin endpoint, partial results and long-running search model.
• OpenSearch async settings — Maximum running time, concurrency, retention and wait timeout settings.
• OpenSearch logs — Request-level and shard-level search slow logs plus task-resource logging.
• OpenSearch tasks API — Task inspection and cancellation mechanisms.