Lab DP1: hot_threads and the Profile API

Background

The intensive gave you a triage tree. This lab makes the top-left branch — "why is it slow / hot?" — muscle memory. You will stand up a local node, generate enough load to make a thread visibly hot, capture GET /_nodes/hot_threads and read the stacks, run a deliberately slow query with "profile": true and decode the per-collector / per-shard timing tree, turn on search and indexing slow logs and read the lines they produce, and finally use _tasks to find and cancel a long-running task. These are the four cheapest, highest-leverage diagnostics in OpenSearch, and a contributor uses them daily.

Why This Matters for Contributors

When you pick up a "search is slow" or "this aggregation is expensive" issue, the maintainers expect a diagnosis, not a guess. "It's slow" is not a bug report; "hot_threads shows 95% in GlobalOrdinalsStringTermsAggregator.collect and the Profile API attributes 80% of query time to the collect phase of a 50k-bucket terms agg" is one — it points at the exact code and the exact cause. This lab is the reps that let you produce that sentence on demand. Everything here runs against a vanilla local node; no special build.

Prerequisites

• A running OpenSearch node. Either an OpenSearch checkout (./gradlew run, which serves on localhost:9200) or any 2.x/3.x install. The intensive and storage-engine assume ./gradlew run.
• curl, python3 (for pretty-printing JSON), and a shell.
• Read the intensive sections "Why is it slow / hot?" and "Why is it stuck?".

Note: A ./gradlew run node is single-node with default settings — one shard per index unless you ask for more. That is fine; everything in this lab works on one node, and a single shard makes the Profile API output short enough to read.

Step-by-Step Tasks

Step 1 — Create an index and load enough data to be interesting

A few thousand docs across a couple of shards, with a high-cardinality field (to make terms aggs expensive) and a text field (to make queries do real work):

# Index with 2 shards so the profile shows per-shard breakdowns.
curl -s -XPUT 'localhost:9200/shop?pretty' -H 'Content-Type: application/json' -d'
{
  "settings": { "number_of_shards": 2, "number_of_replicas": 0 },
  "mappings": { "properties": {
    "sku":      { "type": "keyword" },
    "category": { "type": "keyword" },
    "price":    { "type": "double" },
    "body":     { "type": "text" }
  }}
}'

# Bulk-load 20k docs with a high-cardinality sku and ~200 categories.
python3 - <<'PY' > /tmp/bulk.ndjson
import random
words = "lucene segment slice reduce term postings scorer query phase collect".split()
for i in range(20000):
    print('{"index":{}}')
    print('{"sku":"sku-%d","category":"cat-%d","price":%.2f,"body":"%s"}' % (
        i, i % 200, random.uniform(1, 1000),
        " ".join(random.choice(words) for _ in range(8))))
PY
curl -s -XPOST 'localhost:9200/shop/_bulk?refresh=wait_for' \
  -H 'Content-Type: application/x-ndjson' --data-binary @/tmp/bulk.ndjson | \
  python3 -c 'import sys,json; d=json.load(sys.stdin); print("errors:", d["errors"])'

curl -s 'localhost:9200/_cat/indices/shop?v'

Step 2 — Generate load and capture hot_threads

Drive a continuous stream of an expensive query in the background, then sample the hot threads while it runs. The expensive query: a high-cardinality terms agg, which forces a lot of per-document ordinal work.

# A small load generator: fire the expensive query in a tight loop.
cat > /tmp/load.sh <<'SH'
#!/bin/sh
while true; do
  curl -s 'localhost:9200/shop/_search' -H 'Content-Type: application/json' -d'
  { "size": 0,
    "query": { "match": { "body": "scorer" } },
    "aggs": { "by_sku": { "terms": { "field": "sku", "size": 10000 } } } }' >/dev/null
done
SH
chmod +x /tmp/load.sh

# Run several in parallel to saturate the SEARCH pool, then sample.
for i in 1 2 3 4 5 6; do /tmp/load.sh & done
LOAD_PIDS=$(jobs -p)

sleep 2   # let it warm up
curl -s 'localhost:9200/_nodes/hot_threads?threads=5&interval=1s&type=cpu' | tee /tmp/hot.txt

# Stop the load when done with this step.
kill $LOAD_PIDS 2>/dev/null

Step 3 — Read the hot_threads stacks

Open /tmp/hot.txt. You are looking for three things in each block: the thread name (which pool), the percentage (how hot), and the shared stack (the code).

   91.7% (458.4ms out of 500ms) cpu usage by thread 'opensearch[node-0][search][T#3]'
     8/10 snapshots sharing following 27 elements
       app//org.apache.lucene.index.OrdinalMap...
       app//org.opensearch.search.aggregations.bucket.terms.GlobalOrdinalsStringTermsAggregator$...collect(...)
       app//org.opensearch.search.aggregations.LeafBucketCollector.collect(...)
       app//org.apache.lucene.search.Weight$DefaultBulkScorer.scoreRange(...)
       app//org.opensearch.search.query.QueryPhase...execute(...)

Decode it, writing your answers down:

# Locate the hot class in a checkout to read what collect() actually does:
find server -name GlobalOrdinalsStringTermsAggregator.java
grep -n "collect\|getLeafCollector\|ordinal\|collectExistingBucket\|collectBucket" \
  server/src/main/java/org/opensearch/search/aggregations/bucket/terms/GlobalOrdinalsStringTermsAggregator.java | head

Now compare types — the same load, ranked differently:

for i in 1 2 3 4 5 6; do /tmp/load.sh & done; LOAD_PIDS=$(jobs -p); sleep 2
curl -s 'localhost:9200/_nodes/hot_threads?type=wait&threads=3'   # who is parked?
curl -s 'localhost:9200/_nodes/hot_threads?type=block&threads=3'  # who is lock-blocked?
kill $LOAD_PIDS 2>/dev/null

Note: Under a pure CPU-bound agg load, type=wait/type=block will likely show little — that confirms the bottleneck is CPU, not a lock or pool starvation. A symptom that shows up under block (and not cpu) is the opposite diagnosis: contention, not compute. Knowing which one is empty is itself the answer.

Step 4 — Profile one slow query

Now zoom from "which kind of work" to "where inside the query." Run the same expensive query once, with "profile": true:

curl -s 'localhost:9200/shop/_search' -H 'Content-Type: application/json' -d'
{
  "size": 0,
  "profile": true,
  "query": { "bool": {
      "must":   [ { "match": { "body": "scorer" } } ],
      "filter": [ { "range": { "price": { "gte": 100 } } } ] } },
  "aggs": { "by_sku": { "terms": { "field": "sku", "size": 10000 } } }
}' > /tmp/profile.json
python3 -m json.tool /tmp/profile.json | less

Step 5 — Decode the query timing tree

Pull out the parts that matter. The structure is profile.shards[*].searches[*].{query[], collector[]} and profile.shards[*].aggregations[].

# Per-shard query breakdown -- the dominant field tells you the cost center:
python3 - <<'PY'
import json
d = json.load(open("/tmp/profile.json"))
for sh in d["profile"]["shards"]:
    print("\n=== shard", sh["id"], "===")
    for s in sh["searches"]:
        for q in s["query"]:
            bd = q["breakdown"]
            top = sorted(bd.items(), key=lambda kv: kv[1], reverse=True)[:5]
            print(" QUERY", q["type"], "  total_ns=", q["time_in_nanos"])
            for k, v in top:
                if not k.endswith("_count"):
                    print("    ", k, v)
        for c in s["collector"]:
            print(" COLLECTOR", c["name"], "  time_ns=", c["time_in_nanos"])
    for a in sh.get("aggregations", []):
        bd = a["breakdown"]
        print(" AGG", a["type"], "  total_ns=", a["time_in_nanos"],
              "  collect_ns=", bd.get("collect"))
PY

Interpret what you see against the breakdown table from the intensive:

For this query, expect the aggregation collect to dwarf the query phase — that is the whole point of the load you built, and it agrees with the hot_threads stack from Step 3. Two independent tools, same conclusion: the high-cardinality terms agg is the cost.

flowchart TD
    HT["hot_threads: GlobalOrdinals...collect is 91% CPU"] --> Hyp["hypothesis: the terms agg is the cost"]
    Prof["Profile API: agg.collect_ns >> query time_in_nanos"] --> Hyp
    Hyp --> Conf["confirmed by two tools -> fix the agg, not the query"]

Step 6 — Enable and read slow logs

The Profile API needed you to run the query. Slow logs catch the slow ones automatically. Set low thresholds (so they trip on this load), then generate a slow request:

curl -s -XPUT 'localhost:9200/shop/_settings' -H 'Content-Type: application/json' -d'
{
  "index.search.slowlog.threshold.query.warn":  "10ms",
  "index.search.slowlog.threshold.query.info":  "1ms",
  "index.search.slowlog.threshold.fetch.warn":  "10ms",
  "index.indexing.slowlog.threshold.index.warn":"5ms",
  "index.indexing.slowlog.source": "200"
}'

# Trip the search slow log with the expensive agg:
curl -s 'localhost:9200/shop/_search' -H 'Content-Type: application/json' -d'
{ "size":0, "aggs": { "by_sku": { "terms": { "field": "sku", "size": 10000 } } } }' >/dev/null

# Trip the indexing slow log:
curl -s -XPOST 'localhost:9200/shop/_doc?refresh=true' -H 'Content-Type: application/json' -d'
{ "sku":"sku-slow", "category":"cat-1", "price":9.99, "body":"a slow indexed doc" }' >/dev/null

Find and read the log files (location varies by install; for ./gradlew run they are under the run directory's logs/):

# Locate the slow log files:
find . -name "*_index_search_slowlog.json" 2>/dev/null
find . -name "*_index_indexing_slowlog.json" 2>/dev/null
# Or, for a packaged install:
ls $OPENSEARCH_HOME/logs/*slowlog* 2>/dev/null

# Tail and read one line:
tail -2 $(find . -name "*_index_search_slowlog.json" 2>/dev/null | head -1)

A line carries the shard, the took, the total_hits, and the (truncated) source:

{"type":"index_search_slowlog", ... "message":"[shop][0]", "took":"23.4ms",
 "took_millis":23, "total_hits":"20000 hits", "search_type":"QUERY_THEN_FETCH",
 "source":"{\"size\":0,\"aggs\":{...}}" ...}

Warning: Turn the thresholds back up (or remove them) when you're done — 1ms is a firehose on a busy index. curl -XPUT .../shop/_settings -d '{"index.search.slowlog.threshold.query.info":null}'

Step 7 — Find and cancel a long-running task

Start a deliberately heavy, long search in the background, then find it and cancel it via _tasks.

# A heavy request that runs a while (huge agg, scanned across shards):
curl -s 'localhost:9200/shop/_search' -H 'Content-Type: application/json' -d'
{ "size":0, "aggs": { "a": { "terms": { "field": "sku", "size": 20000 },
   "aggs": { "b": { "terms": { "field": "category", "size": 200 } } } } } }' >/dev/null &
SEARCH_BG=$!

# Immediately list running search tasks with detail and runtime:
sleep 1
curl -s 'localhost:9200/_tasks?actions=*search*&detailed' | python3 - <<'PY'
import sys, json
d = json.load(sys.stdin)
for node, n in d["nodes"].items():
    for tid, t in n["tasks"].items():
        print(tid, t["action"], "running_ms=", t["running_time_in_nanos"]//1_000_000,
              "cancellable=", t.get("cancellable"))
        print("   desc:", t.get("description","")[:80])
PY

Take the task id (<node-id>:<number>) of the search action and cancel it:

TASK="<paste-the-node-id:number-here>"
curl -s -XPOST "localhost:9200/_tasks/${TASK}/_cancel" | python3 -m json.tool

# Or cancel ALL search tasks at once:
curl -s -XPOST 'localhost:9200/_tasks/_cancel?actions=*search*' | python3 -m json.tool
wait $SEARCH_BG 2>/dev/null

# Read why cancellation works (the task must cooperate by checking isCancelled):
grep -n "isCancelled\|ensureNotCancelled\|CancellableTask\|registerCancellable" \
  server/src/main/java/org/opensearch/tasks/TaskManager.java \
  server/src/main/java/org/opensearch/search/query/QueryPhase.java 2>/dev/null | head

The cancelled search returns a partial/error response rather than running to completion — proof the search path honors isCancelled() at its check points.

Deliverables

• /tmp/hot.txt showing a [search] thread >80% CPU with a GlobalOrdinalsStringTermsAggregator...collect stack and N/10 snapshots sharing.
• /tmp/profile.json plus your decoded breakdown identifying the dominant cost center (the agg collect), agreeing with the hot-thread stack.
• A search slow-log line and an indexing slow-log line, with the shard, took, and source called out.
• A _tasks listing of a running search and the _cancel response, plus the one-line explanation of why cancellation is cooperative.

Expected Output

# hot_threads (Step 2-3)
   91.7% (458.4ms out of 500ms) cpu usage by thread 'opensearch[node-0][search][T#3]'
     8/10 snapshots sharing following 27 elements
       ...GlobalOrdinalsStringTermsAggregator...collect(...)

# profile decode (Step 5)
=== shard 0 ===
 QUERY BooleanQuery   total_ns= 4120333
     build_scorer 2100000
     next_doc      900000
 COLLECTOR MultiCollector   time_ns= 41233111
 AGG GlobalOrdinalsStringTerms total_ns= 39800000  collect_ns= 37100000   <-- the cost

# slow log (Step 6)
{"type":"index_search_slowlog", "message":"[shop][0]", "took":"23.4ms", "total_hits":"20000 hits", ...}

# tasks (Step 7)
node-0:1487 indices:data/read/search running_ms= 1203 cancellable= True
{"task":{"node":"node-0","id":1487,...}}   # _cancel acknowledged

Troubleshooting

Stretch Goals

• Make next_doc dominate instead of agg collect. Drop the agg and run a broad match over body; re-profile and confirm the cost moves into the query phase's next_doc.
• Turn the agg into a filter to kill scoring. Move the match into a filter clause (constant_score) and show score drops out of the breakdown.
• Per-shard skew. Index unevenly (most docs to one shard) and show the slow log fires for only that shard while the other is fast — per-shard logging in action.
• Profile a k-NN query. If you have the k-NN plugin, profile a knn query and find the graph-traversal time; cross-link vector-internals.

Coding Exercises

You ran these diagnostics by hand; now turn each into code that parses the output or asserts the behavior, so a regression would be caught automatically. Locate every class with rg/find first — never trust a line number from this page.

1. (warm-up) A hot_threads parser. Write a standalone Python program parse_hot.py that reads /tmp/hot.txt and emits, per block, a tuple of (pool_name, cpu_percent, snapshots_shared, top_app_frame) — where pool_name is parsed from 'opensearch[...][search][T#3]' and top_app_frame is the first app//org.opensearch... line. Verify it prints search 91.7 8 GlobalOrdinals... for the Step 3 capture. Add a --min-cpu 80 flag that filters to genuinely hot threads. This is the script you'll paste into an issue to summarize a dump.

2. (core) A Profile-API breakdown asserter. Extend the Step 5 Python into a function dominant_cost(profile_json) -> str returning one of {"query:build_scorer","query:next_doc","agg:collect", ...} by ranking the per-shard breakdown fields. Then write a tiny test (plain asserts) that runs the two queries from the lab — the agg-heavy one and a bare match — and asserts the first returns agg:collect and the second returns a query:* field. You are encoding the triage tree from the intensive as executable rules.

3. (core) A unit test for cooperative cancellation. Find the cancellation check points the search path honors:

   rg -n "isCancelled|ensureNotCancelled|addQueryCancellation|checkCancelled" \
     server/src/main/java/org/opensearch/search/query/QueryPhase.java \
     server/src/main/java/org/opensearch/search/internal/ContextIndexSearcher.java
   

   Write an OpenSearchTestCase/AggregatorTestCase-style unit test that builds a SearchContext (or a ContextIndexSearcher) whose cancellation supplier throws, and asserts the query phase aborts with the expected exception rather than running to completion. Model it on the existing *CancellationTests/*CancellableTests you find with rg -l "Cancell" server/src/test.

4. (advanced) An instrumentation patch that proves the slow-log path. Add a temporary counter or log line in the search slow-log emitter — find it with

   rg -n "class SearchSlowLog|logSlowSearch|onQueryPhase|SlowLogLevel" \
     server/src/main/java/org/opensearch/index/SearchSlowLog.java
   

   then write an OpenSearchIntegTestCase (extend OpenSearchSingleNodeTestCase for speed) that sets index.search.slowlog.threshold.query.warn to 0ms, runs a search, and asserts via a MockLogAppender that a slow-log event with the shard id fired. (rg -l "MockLogAppender" server/src/test for the harness pattern.) This is how OpenSearch itself tests its slow logs — you're writing a real regression test.

5. (Advanced challenge) A _tasks-driven cancellation integration test. Write an OpenSearchIntegTestCase that: (a) launches a deliberately expensive search asynchronously, (b) polls the Tasks API (client().admin().cluster().prepareListTasks() filtered to *search*) until it appears, (c) cancels it (prepareCancelTasks), and (d) asserts the search future completes with a cancellation/TaskCancelledException rather than a normal result, and that the task disappears from the list afterward. Find existing patterns with rg -ln "PluginsService|ListTasksRequest|CancelTasksRequest|MockSearchService" server/src/test test. Bonus: register a SearchOperationListener (rg -n "SearchOperationListener" server/src/main) that records how many docs were collected before the cancel landed, proving cancellation is cooperative (it stops at a check point, not instantly). This single test exercises the whole Step 7 workflow as a graded artifact.

Issues to Practice On

These diagnostics are exactly what maintainers ask for on performance issues — pick one and bring the artifact, not a guess.

Label taxonomies drift; list them first with gh label list --repo opensearch-project/OpenSearch and pick the closest area.

Representative patterns. (a) "Aggregation X is slower than it should be" — the report is vague; your job is to make it concrete: reproduce on a ./gradlew run node, capture hot_threads + a "profile":true run, and post the dominant breakdown field with the named class (the sentence this whole lab teaches). That diagnosis often is the accepted fix's starting point. (b) "Slow log doesn't report field Y" or a threshold/format bug — reproduce → locate via rg "SearchSlowLog|IndexingSlowLog" → fix → add a MockLogAppender test → PR with a CHANGELOG entry and DCO sign-off.

Planted-bug drill. Find the slow-log threshold comparison:

rg -n "threshold|warnThreshold|infoThreshold|>=|setLevel" \
  server/src/main/java/org/opensearch/index/SearchSlowLog.java

Invert one comparison (e.g. flip a >= to > on the warn threshold, or swap the warn/info levels) and run the relevant SearchSlowLogTests (rg -l "class SearchSlowLogTests" server/src/test). Watch which assertion goes red, then revert and add an assertion that pins the exact boundary (a took equal to the threshold should/shouldn't fire) — the kind of edge a real bug slips through.

Etiquette: claim the issue with a comment before working it, reproduce first, and every PR needs a test + a CHANGELOG.md entry + a DCO Signed-off-by (git commit -s). See community-interaction.

Validation / Self-check

• You can run _nodes/hot_threads with the right type/threads/interval and read a stack to name the pool and the suspected class.
• You can profile a query, identify the dominant breakdown field, and explain what it measures — and why the absolute nanos are inflated.
• You can configure search and indexing slow logs, trip them, and read the shard/took/source from a line.
• You can find a running task with _tasks?detailed, cancel it, and explain why cancellation is cooperative.
• Given hot_threads and a Profile API result that agree, you can state a one-sentence root cause that points at a specific class.

Next: Lab DP2 — JFR and async-profiler, where the hot path is too deep or too native for hot_threads and you reach for flame graphs.