Debugging and Profiling — Intensive
Every other masterclass teaches you how a subsystem is supposed to work. This
one teaches you what to do when it doesn't — when a node is pinned at 100% CPU,
when a query that should take 5ms takes 5s, when the heap fills and the JVM
OutOfMemoryErrors, or when an aggregation returns the wrong number. The skill
that separates a senior OpenSearch contributor from a beginner is not knowing the
code; it is knowing, under pressure, which tool answers which question — and
being able to drive that tool to a root cause instead of guessing.
This chapter is organized around four questions a contributor actually asks:
- Why is it slow / hot? —
_nodes/hot_threads, the Profile API, slow logs. - Why is it stuck? — thread dumps,
_tasks+ cancellation, blocked pools. - Why is it OOM? — heap dumps → Eclipse MAT, circuit breakers,
_nodes/stats. - Why is it wrong? — TRACE logging, a deterministic reproducer,
git bisect.
It extends, and assumes you have read, three deep-dives:
threadpools-concurrency (the pools a
hot thread runs on, the cardinal "never block coordination threads" rule),
circuit-breakers-memory (the breakers
that trip before OOM), and search-execution
(the query/fetch phases the Profile API breaks down). It also introduces the
in-tree telemetry framework (org.opensearch.telemetry) and shows you how to
add a span or a metric to a code path you are debugging.
Note: Throughout, the term cluster manager (formerly master) refers to the elected node that maintains and publishes cluster state. Several "stuck" symptoms below cascade from a thread that blocks the cluster-manager update or applier thread; that cascade is drawn in threadpools-concurrency.
The labs that go with this chapter:
- Lab DP1: hot_threads and the Profile API — generate load, read hot-thread stacks, decode a Profile API timing tree, read slow logs, find + cancel a runaway task.
- Lab DP2: JFR and async-profiler — attach Java
Flight Recorder and async-profiler to a live node, read CPU and allocation flame
graphs, tie an allocation hotspot to
BigArrays. - Lab DP3: Heap and Thread Dumps — diagnose a deadlock from a thread dump, find a retained-memory culprit in Eclipse MAT, read GC logs.
- Lab DP4: Reproduce and Bisect a Bug — build a
deterministic reproducer, add TRACE logging, attach a debugger via
./gradlew run --debug-jvm, andgit bisectto the introducing PR.
The triage decision tree
Before any specific tool, internalize the order of operations. The mistake
beginners make is reaching for a heap dump (slow, heavy, hard to read) when
hot_threads (one HTTP call, instant) would have answered the question. Start at
the top and only descend when the cheaper tool is inconclusive.
flowchart TD
Start{"What is the symptom?"} --> Slow["slow / high CPU"]
Start --> Stuck["hung / not progressing"]
Start --> OOM["heap pressure / OOM"]
Start --> Wrong["wrong result"]
Slow --> HT["GET _nodes/hot_threads<br/>(who is burning CPU?)"]
HT --> Prof["one slow query?<br/>_search {profile:true}"]
HT --> JFR["whole-node CPU?<br/>JFR / async-profiler flame graph"]
Prof --> SlowLog["recurring?<br/>enable search/index slow logs"]
Stuck --> Tasks["GET _tasks?detailed<br/>(what is running, for how long?)"]
Tasks --> Cancel["runaway task?<br/>POST _tasks/<id>/_cancel"]
Tasks --> Dump["no progress at all?<br/>jstack / jcmd Thread.print"]
Dump --> Pool["BLOCKED on a fixed pool<br/>or a coordination thread?"]
OOM --> Stats["GET _nodes/stats (heap, breakers, fielddata)"]
Stats --> Breaker["breaker tripping?<br/>which one, what limit?"]
Stats --> Heap["leak / retention?<br/>jmap heap dump -> Eclipse MAT"]
Heap --> GC["GC thrash?<br/>read -Xlog:gc* logs"]
Wrong --> Trace["TRACE logging on the suspect logger"]
Trace --> Repro["deterministic reproducer<br/>(-Dtests.seed, curl script)"]
Repro --> Bisect["regression?<br/>git bisect 2.x..main"]
Repro --> Debug["step through:<br/>./gradlew run --debug-jvm (attach 5005)"]
Memorize the first box under each symptom: hot_threads for slow, _tasks for
stuck, _nodes/stats for OOM, TRACE logging for wrong. Those four calls cost you
seconds and route you to the right heavyweight tool.
Why is it slow / hot?
_nodes/hot_threads — the first call, always
GET /_nodes/hot_threads is implemented by org.opensearch.action.admin.cluster.node.hotthreads.HotThreads.
It is a sampling thread profiler built into the cluster: it snapshots every
live thread's stack, sleeps a short interval (default 500ms), snapshots again,
and reports the threads whose CPU/wait/block time grew the most — with their
stacks. It needs no agent, no restart, no port; it is one HTTP call against a
running node.
# The default: the 3 hottest threads per node, by CPU, 10 samples.
curl -s 'localhost:9200/_nodes/hot_threads'
# Tune it: more threads, longer window, and choose what "hot" means.
curl -s 'localhost:9200/_nodes/hot_threads?threads=5&interval=1s&type=cpu'
curl -s 'localhost:9200/_nodes/hot_threads?type=wait' # who is parked/waiting
curl -s 'localhost:9200/_nodes/hot_threads?type=block' # who is blocked on a monitor
type= | What it ranks by | Use when |
|---|---|---|
cpu (default) | CPU time consumed between samples | node is CPU-bound, fans spinning |
wait | time spent in WAITING/TIMED_WAITING | threads parked — pool starvation, lock waits |
block | time BLOCKED on a monitor | lock contention — two threads fighting for a synchronized |
# Find the implementation and the percentage/idle-filtering logic in a checkout:
find server -name HotThreads.java
grep -n "type\|interval\|isIdleThread\|percent\|busiest\|innerDetect" \
server/src/main/java/org/opensearch/action/admin/cluster/node/hotthreads/HotThreads.java | head
The output is a percentage and a stack:
::: {node-0}{...}
Hot threads at 2026-06-16T..., interval=500ms, busiestThreads=3, type=cpu:
98.4% (492ms out of 500ms) cpu usage by thread 'opensearch[node-0][search][T#7]'
10/10 snapshots sharing following 23 elements
app//org.apache.lucene.search.DisjunctionScorer.score(...)
app//org.opensearch.search.aggregations.bucket.terms.GlobalOrdinalsStringTermsAggregator...collect(...)
app//org.opensearch.search.query.QueryPhase.execute(...)
...
Read it like this:
- The thread name tells you the pool.
[search]→ theSEARCHpool, so this is query/fetch work.[write],[refresh],[clusterApplierService],[generic]— each maps to a pool from threadpools-concurrency. A hot[clusterApplierService]thread is an emergency: state application is stalling. N/10 snapshots sharingis the consensus.10/10 sharingmeans the thread sat in that exact stack the whole window — a tight loop or genuinely expensive call.3/10means it churned through many stacks; look higher up the frames for the common ancestor.- The stack is your map into the code. The frame
GlobalOrdinalsStringTermsAggregatorsays "atermsaggregation on a high-cardinality field"; you now grep that class and reason about cardinality.
Note:
hot_threadsis the single highest-leverage diagnostic in OpenSearch. It is safe to run in production, costs almost nothing, and answers "what is this node doing right now?" before you reach for anything heavier. Lab DP1 makes you read real stacks under load.
The Profile API — one query, broken down
hot_threads tells you which kind of work is hot. When the answer is "one
specific slow query," the Profile API tells you where inside that query the
time goes. Add "profile": true to any _search body:
curl -s 'localhost:9200/orders/_search' -H 'Content-Type: application/json' -d'
{
"profile": true,
"query": { "bool": { "must": [ {"match": {"body": "lucene"}} ],
"filter": [ {"range": {"price": {"gte": 10}}} ] } },
"aggs": { "by_cat": { "terms": { "field": "category", "size": 20 } } }
}' | python3 -m json.tool
The response carries a profile block with per-shard, per-query timings. The
key breakdown fields, in nanoseconds:
| Breakdown field | What it measures | A spike here means |
|---|---|---|
create_weight | building the Weight (one-time per query) | expensive query construction (huge terms, many clauses) |
build_scorer | constructing the Scorer per segment | iterator/postings setup — many segments, costly filters |
next_doc | advancing to the next matching doc | the matching scan itself — selectivity, postings size |
advance | Scorer.advance(target) (used by conjunctions) | leapfrogging cost in bool/filter intersections |
score | computing the BM25/similarity score per doc | scoring a huge result set; consider filter not must |
match | two-phase TwoPhaseIterator.matches() | expensive confirmation (phrase, geo) per candidate |
The aggregation profile is separate, under aggregations, with its own
breakdown: initialize, collect (the hot one — per-doc bucketing),
build_aggregation, reduce. A terms agg dominated by collect is doing a lot
of per-document ordinal lookups; cross-reference
aggregations for the GlobalOrdinalsStringTermsAggregator
internals.
flowchart TD
Resp["_search profile response"] --> Shards["profile.shards[]"]
Shards --> Q["searches[].query[]<br/>(the query tree)"]
Shards --> C["searches[].collector[]<br/>(collector wall-time)"]
Shards --> A["aggregations[]<br/>(per-agg breakdown)"]
Q --> BD["breakdown:<br/>create_weight / build_scorer /<br/>next_doc / advance / score / match"]
A --> ABD["breakdown:<br/>initialize / collect /<br/>build_aggregation / reduce"]
Two cautions that trip everyone up the first time:
Warning: Profiling has overhead — every
next_doc/advancecall is wrapped and timed. Absolute numbers are inflated; use the Profile API to find the relative hotspot (which clause, which collector), not to quote a real latency. Andtime_in_nanosis per shard; the coordinator-side merge/reduce is not in the per-shard tree (the aggreduceyou see is the shard-local partial reduce).
Lab DP1 decodes a real timing tree end-to-end.
Slow logs — catch the slow ones you didn't run by hand
The Profile API needs you to run the slow query. Slow logs catch the slow queries that already happened, in production, per shard, automatically. They are configured by dynamic index settings with per-level thresholds:
curl -s -XPUT 'localhost:9200/orders/_settings' -H 'Content-Type: application/json' -d'
{
"index.search.slowlog.threshold.query.warn": "2s",
"index.search.slowlog.threshold.query.info": "1s",
"index.search.slowlog.threshold.fetch.warn": "500ms",
"index.indexing.slowlog.threshold.index.warn":"1s",
"index.indexing.slowlog.source": "1000"
}'
| Setting prefix | Logs when | Written to |
|---|---|---|
index.search.slowlog.threshold.query.* | the query phase on a shard exceeds the threshold | *_index_search_slowlog.json |
index.search.slowlog.threshold.fetch.* | the fetch phase (stored-field load) exceeds it | same |
index.indexing.slowlog.threshold.index.* | indexing a doc on a shard exceeds it | indexing slowlog |
Each threshold has warn/info/debug/trace levels so you can keep a noisy
info channel and a quiet warn channel. The log line names the shard, the
took time, and (truncated to index.indexing.slowlog.source) the source — so
you can reproduce it.
# Tail them (path is logs/<cluster>_index_search_slowlog.json under your data/logs dir):
tail -f $OPENSEARCH_HOME/logs/*_index_search_slowlog.json | python3 -m json.tool 2>/dev/null
grep -n "slowlog\|SearchSlowLog\|IndexingSlowLog\|threshold" \
server/src/main/java/org/opensearch/index/SearchSlowLog.java
Note: Slow-log thresholds are per shard, not per request. A search that hits 5 shards and is slow on only one logs once, for that shard. That is a feature: it tells you which shard is the laggard — often a hot shard or a cold one with an unwarmed page cache (see storage-engine).
Why is it stuck?
"Slow" means progress, just too little. "Stuck" means no progress: a request
that never returns, a node that stops accepting work, a relocation that never
finishes. The first call is _tasks, not a thread dump.
_tasks + cancellation
OpenSearch tracks in-flight work in a TaskManager. GET /_tasks lists every
running task, its parent, the node, and how long it has run. This is how you find
the one query that has been running for 40 seconds:
# All running tasks, with detail and runtime, grouped by parent:
curl -s 'localhost:9200/_tasks?detailed&group_by=parents' | python3 -m json.tool
# Just search tasks, sorted to find the long pole:
curl -s 'localhost:9200/_tasks?actions=*search*&detailed' | python3 -m json.tool
# A task shows running_time_in_nanos and the description (the query, for search).
When you find the culprit — a runaway aggregation, a scroll that's pinning
segments, a reindex gone wrong — cancel it. Cancellation is cooperative: the
task must check isCancelled() at safe points, which search and many bulk
operations do.
# Cancel one task by id (node:taskNumber), or all of a kind:
curl -s -XPOST 'localhost:9200/_tasks/<node-id>:<task-number>/_cancel'
curl -s -XPOST 'localhost:9200/_tasks/_cancel?actions=*reindex*'
grep -n "class TaskManager\|isCancelled\|cancelTaskAndDescendants\|registerCancellable" \
server/src/main/java/org/opensearch/tasks/TaskManager.java | head
Lab DP1 walks finding and cancelling a long task end to end.
Thread dumps — when nothing is progressing
If _tasks shows tasks that are stuck (running, but running_time not advancing
across two calls), or the node isn't even answering _tasks, take a thread
dump. A thread dump is a snapshot of every thread's stack and state — the
ground truth of what the JVM is doing.
# Find the node PID (a ./gradlew run node, or a real install):
PID=$(jps -l | grep -i 'opensearch\|Bootstrap' | awk '{print $1}'); echo $PID
# Two equivalent ways to dump:
jstack -l "$PID" > /tmp/dump1.txt # -l also lists owned locks
jcmd "$PID" Thread.print > /tmp/dump1.txt # same content via the jcmd interface
# Take THREE dumps a few seconds apart -- one is a photo, three is a movie:
for i in 1 2 3; do jstack "$PID" > /tmp/dump$i.txt; sleep 5; done
What to look for, in priority order:
| In the dump | Means |
|---|---|
"...[search][T#k]" ... java.lang.Thread.State: BLOCKED (on object monitor) and - waiting to lock <0x...> | lock contention; find who - locked <0x...> that same monitor |
Many [search]/[write] threads all BLOCKED on the same lock | a fixed pool is wedged — search/indexing stalls (see threadpools) |
"clusterApplierService#updateTask" not WAITING for work | the applier thread is blocked — cluster state can't apply, the cluster manager may step down |
Thread A waiting to lock X while holding Y, thread B waiting to lock Y while holding X | a classic deadlock — jstack prints a Found one Java-level deadlock summary |
jstack detects deadlocks for you and prints a Found one Java-level deadlock:
block at the end listing the cycle — that is the single most valuable line in the
file. Lab DP3 builds and diagnoses a deadlock from
a dump.
flowchart LR
Stuck["request never returns"] --> T["GET _tasks?detailed"]
T -->|"task present, time not moving"| D["jstack x3"]
T -->|"runaway task"| Cancel["_tasks/<id>/_cancel"]
D -->|"BLOCKED on monitor"| Lock["find the lock holder"]
D -->|"deadlock summary"| DL["fix the lock ordering"]
D -->|"all pool threads parked"| Star["pool starvation / blocking work on a fixed pool"]
Why is it OOM?
Heap pressure is the most dangerous failure: it degrades the whole node, then kills it. OpenSearch's first line of defense is circuit breakers (covered in circuit-breakers-memory) — they trip and reject a request before it OOMs the node. So the first question is not "where is the leak" but "is a breaker tripping, and which one?"
_nodes/stats — heap, breakers, and what's holding memory
# Heap usage and GC:
curl -s 'localhost:9200/_nodes/stats/jvm?filter_path=nodes.*.jvm.mem.heap_used_percent,nodes.*.jvm.gc' \
| python3 -m json.tool
# Circuit breakers: tripped counts and current estimated bytes vs limit:
curl -s 'localhost:9200/_nodes/stats/breaker' | python3 -m json.tool
# The memory-hungry caches: fielddata, query cache, request cache, segments:
curl -s 'localhost:9200/_nodes/stats/indices/fielddata,query_cache,request_cache,segments' \
| python3 -m json.tool
Breaker (org.opensearch.indices.breaker) | Guards against | Common trigger |
|---|---|---|
parent | total of all child breakers vs indices.breaker.total.limit (default ~95% heap, real-memory aware) | overall heap pressure |
fielddata | heap held by field data for text/sorting/aggs on non-doc-values | aggregating/sorting a text field |
request | per-request data structures (agg BigArrays) vs indices.breaker.request.limit | a huge aggregation (high-cardinality terms) |
in_flight_requests | bytes of in-flight transport/HTTP request bodies | huge bulk/search bodies |
accounting | memory accounted after a request (e.g. Lucene segment readers) | many large segments |
A rising tripped count on request with a CircuitBreakingException in the
logs is the textbook "my aggregation is too big" signal — the breaker did its job
and protected the node. The fix is a smaller agg (size, partitions), not a
bigger limit. See aggregations for MultiBucketConsumer
and search.max_buckets.
Heap dumps → Eclipse MAT
When the heap is genuinely retained (a leak, or one giant structure) and breakers aren't catching it, take a heap dump and open it in Eclipse Memory Analyzer (MAT). This is heavy (the dump is roughly the size of the live heap, and writing it pauses the JVM), so it is the last resort, not the first.
# Trigger on OOM automatically (set in jvm.options / JVM args BEFORE the crash):
# -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/var/lib/opensearch/heapdumps
# Or take one on demand from a live (struggling) node:
jcmd "$PID" GC.heap_dump /tmp/heap.hprof # preferred, uses the JVM's own writer
jmap -dump:live,format=b,file=/tmp/heap.hprof "$PID" # ":live" forces a GC first
In MAT, work top-down:
| MAT view | What it answers |
|---|---|
| Leak Suspects report | MAT's automatic guess: "X is keeping N% of the heap alive via Y" |
| Dominator Tree | sorted by retained size — the object that, if freed, frees the most. The real culprit lives here. |
| Histogram | instances per class — millions of byte[]/BytesRef/long[] points at fielddata or BigArrays |
| Path to GC Roots (exclude weak/soft) | why a suspected-leaked object is still reachable |
For OpenSearch specifically, the usual heap-dump culprits are a large
fielddata structure (you aggregated/sorted a text field — see
docvalues-fielddata), a giant
aggregation result tree, or a BigArrays-backed buffer that a query is still
holding. Lab DP3 finds a retained fielddata
structure in MAT's dominator tree.
GC logs — is it a leak or just thrash?
Before concluding "leak," check whether GC is keeping up. Enable unified GC logging:
# In jvm.options (the default OpenSearch config already enables a variant of this):
# -Xlog:gc*,gc+age=trace,safepoint:file=logs/gc.log:utctime,pid,tags:filecount=32,filesize=64m
grep -n "Xlog:gc\|gc.log\|HeapDumpOnOutOfMemory" config/jvm.options
Read the log for the pattern, not single lines:
| GC log pattern | Diagnosis |
|---|---|
Pause Full collections that don't reclaim much; used-after stays high | a genuine leak or undersized heap — heap dump time |
| Frequent young GCs, healthy reclaim, stable old gen | normal churn — chase allocation rate (async-profiler -e alloc), not a leak |
Long Pause times (seconds) | GC pauses are the latency spike — too-large heap, or G1 region pressure |
Lab DP3 reads a GC log alongside the heap dump so you can tell thrash from leak.
Why is it wrong?
A wrong result (a count off by one, a missing bucket, a mis-scored doc) is a different discipline from a performance problem. You are not measuring; you are narrowing. Three tools, in order.
TRACE logging
OpenSearch uses Log4j2; almost every interesting class has a logger you can crank
to TRACE at runtime, no restart:
# Turn on TRACE for a specific package on a live cluster:
curl -s -XPUT 'localhost:9200/_cluster/settings' -H 'Content-Type: application/json' -d'
{ "transient": { "logger.org.opensearch.search.aggregations": "TRACE" } }'
# ... reproduce the wrong result, read the log, then TURN IT OFF (TRACE is a firehose):
curl -s -XPUT 'localhost:9200/_cluster/settings' -H 'Content-Type: application/json' -d'
{ "transient": { "logger.org.opensearch.search.aggregations": null } }'
# Find the logger name to target -- it's the class's package:
grep -rn "private static final Logger\|LogManager.getLogger" \
server/src/main/java/org/opensearch/search/aggregations/ | head
Warning: TRACE on a busy logger can produce gigabytes a minute and itself slow the node enough to change behavior (a Heisenbug). Scope it to the narrowest package, reproduce once, and turn it off immediately. Prefer a single-shard test index so the log is readable.
A deterministic reproducer
You cannot debug what you cannot reproduce on demand. The goal is a script or test that fails every time:
- A
curlscript that creates a tiny index, indexes known docs, runs the query, anddiffs the result against the expected JSON. - A failing
OpenSearchIntegTestCase/AggregatorTestCase— the gold standard, because it runs in the build andgit bisectcan drive it. OpenSearch tests are randomized; pin the randomness so the failure is stable:
# Pin the random seed so the test takes the SAME path every run:
./gradlew :server:test --tests "org.opensearch.search.aggregations.MyAggTests" \
-Dtests.seed=DEADBEEFCAFE -Dtests.iters=1
A reproducer that fails deterministically is 80% of the fix. Lab DP4 builds one and pins the seed.
git bisect — find the PR that introduced it
If the bug is a regression (it worked in 2.11, it's broken in 2.15),
git bisect finds the introducing commit in O(log n) steps by binary-searching
the history with your reproducer as the test:
git bisect start
git bisect bad main # current HEAD is broken
git bisect good 2.11.0 # this tag was fine
# git checks out the midpoint; run your reproducer and tell it the verdict:
git bisect run ./gradlew :server:test --tests "...MyAggTests" -Dtests.seed=DEADBEEFCAFE
# bisect converges on the first BAD commit -> read its PR and the GitHub discussion.
git bisect reset
The payoff is the introducing PR — its description, review comments, and linked issue usually tell you why the change was made, which is half of how to fix it without re-breaking the original intent. Lab DP4 runs a full bisect across tags and reads the resulting PR.
./gradlew run --debug-jvm — step through it
When TRACE isn't enough, attach a real debugger. From an OpenSearch checkout:
# Start a node that suspends and waits for a debugger to attach on port 5005:
./gradlew run --debug-jvm
# It prints: "Listening for transport dt_socket at address: 5005"
# In IntelliJ: Run -> Attach to Process / a Remote JVM Debug config on localhost:5005.
# Debug a single TEST instead (suspends, waits on 5005):
./gradlew :server:test --tests "org.opensearch.search.aggregations.MyAggTests" --debug-jvm
Set a breakpoint in the suspect collect() / reduce() / toQuery() method, hit
it with your reproducer, and inspect the live state. Lab
DP4 attaches on 5005 and steps through a real
code path.
The JVM tooling table
These are the off-the-shelf JVM tools the sections above lean on. They ship with the JDK (except async-profiler) and attach to any running JVM by PID.
| Tool | Invocation | Gives you | Use for |
|---|---|---|---|
jps | jps -l | PIDs + main classes of running JVMs | finding the node PID |
jstack | jstack -l <pid> | thread dump + lock ownership + deadlock detection | "why is it stuck?" |
jcmd | jcmd <pid> <command> | the swiss-army diagnostic: Thread.print, GC.heap_dump, JFR.start/dump, VM.flags, GC.class_histogram | everything; the modern front door |
jmap | jmap -histo:live <pid> / -dump:live,... | class histogram / full heap dump | OOM / retention |
jstat | jstat -gcutil <pid> 1s | live GC stats every second | quick "is GC the problem?" |
| JFR | -XX:StartFlightRecording=... or jcmd <pid> JFR.start | low-overhead always-on recording: CPU, alloc, locks, I/O, GC | continuous + post-hoc profiling |
| async-profiler | asprof -e cpu/-e alloc/-e lock -d 30 -f flame.html <pid> | accurate sampling flame graphs (CPU, allocations, locks) | CPU/alloc hotspots, beats JFR for native frames |
| GC logs | -Xlog:gc*:file=gc.log | full GC event log | leak vs thrash |
# jcmd is the front door -- list everything a live node supports:
jcmd "$PID" help
# A fast class histogram without a full dump (top heap consumers by class):
jcmd "$PID" GC.class_histogram | head -30
JFR and async-profiler are the heavy hitters; Lab DP2 drives both against a live node under load and reads the flame graphs.
The in-tree telemetry framework
Everything above is external tooling. OpenSearch also ships an internal
observability layer under org.opensearch.telemetry — distributed tracing and a
metrics framework — and as a contributor you will sometimes need to add a span
or a metric to make a code path observable. This is the production successor to
"add a log line."
find . -path "*telemetry*" -name "*.java" | grep -iE "Tracer|Span|MetricsRegistry|Counter|Histogram" | head
grep -rn "interface Tracer\|interface Span\|class SpanScope\|interface MetricsRegistry" \
libs/telemetry/src/main/java/org/opensearch/telemetry/ 2>/dev/null | head
Tracing: Tracer / Span / SpanScope
Type (org.opensearch.telemetry.tracing.*) | Role |
|---|---|
Tracer | the entry point: startSpan(SpanCreationContext) opens a span; the no-op tracer is used when tracing is off |
Span | one unit of work with a start/end, a parent, attributes (addAttribute), and events |
SpanScope | makes a span "current" on the thread (try-with-resources) so child spans nest under it |
SpanContext | the propagatable identity (trace id, span id) carried across threads/nodes via ThreadContext |
The OpenTelemetry implementation lives in the telemetry-otel plugin
(plugins/telemetry-otel), which exports spans via OTLP to a collector. The core
only depends on the Tracer/Span interfaces; the plugin provides the real
exporter. Tracing is gated by cluster settings (e.g.
telemetry.tracer.enabled, with sampling settings) so it costs nothing when off.
Adding a span around code you are profiling:
// Inject the Tracer (it's available to components via the plugin/Node wiring).
import org.opensearch.telemetry.tracing.Tracer;
import org.opensearch.telemetry.tracing.Span;
import org.opensearch.telemetry.tracing.SpanScope;
import org.opensearch.telemetry.tracing.SpanCreationContext;
Span span = tracer.startSpan(SpanCreationContext.internal().name("agg.collect"));
try (SpanScope scope = tracer.withSpanInScope(span)) {
span.addAttribute("agg.type", "terms");
span.addAttribute("field", fieldName);
// ... the work you want to time / trace ...
} catch (Exception e) {
span.setError(e);
throw e;
} finally {
span.endSpan();
}
Metrics: MetricsRegistry / Counter / Histogram
The metrics framework is the counterpart for aggregate numbers — counts and distributions, not per-request spans:
Type (org.opensearch.telemetry.metrics.*) | Use for |
|---|---|
MetricsRegistry | the factory: createCounter(name, desc, unit), createHistogram(...), async gauges |
Counter | a monotonically increasing (or up/down) count — add(value, Tags) |
Histogram | a distribution of recorded values — record(value, Tags) (e.g. latencies) |
Tags | dimensions attached to a measurement (index, shard, node) for slicing |
import org.opensearch.telemetry.metrics.MetricsRegistry;
import org.opensearch.telemetry.metrics.Counter;
import org.opensearch.telemetry.metrics.Histogram;
import org.opensearch.telemetry.metrics.tags.Tags;
// Created once, at component construction:
Counter rejected = metricsRegistry.createCounter("search.rejected.count",
"rejected search tasks", "1");
Histogram collectMs = metricsRegistry.createHistogram("agg.collect.latency",
"per-shard agg collect time", "ms");
// On the hot path:
rejected.add(1.0, Tags.create().addTag("index", indexName));
collectMs.record(elapsedMs, Tags.create().addTag("agg", "terms"));
How a stat surfaces in _nodes/stats
The telemetry framework (OTLP export) is separate from the node stats path you
hit with GET /_nodes/stats. Those classic stats are wired differently: a
subsystem implements a *Stats object that is Writeable + ToXContent, the
node's NodeService/*Service collects it, and NodesStatsRequest/NodeStats
serializes it into the REST response. When you add a new counter that should show
up in _nodes/stats, you extend the relevant Stats class and its serialization,
not the telemetry registry.
# How an existing stat flows from a service into _nodes/stats:
grep -rn "implements Writeable\|implements ToXContent\|class .*Stats" \
server/src/main/java/org/opensearch/index/search/stats/SearchStats.java | head
grep -rn "class NodeStats\|class NodesStatsRequest\|toXContent" \
server/src/main/java/org/opensearch/action/admin/cluster/node/stats/ | head
flowchart LR
Code["your code path"] -->|"span"| Tracer["Tracer.startSpan"]
Code -->|"counter/histogram"| MR["MetricsRegistry"]
Tracer --> OTel["telemetry-otel plugin"]
MR --> OTel
OTel -->|"OTLP"| Collector["external collector (Jaeger/Prometheus)"]
Code2["subsystem *Stats"] -->|"Writeable + ToXContent"| NS["NodeStats"]
NS -->|"GET _nodes/stats"| REST["REST response"]
Note: Distinguish the two. Telemetry (
Tracer/MetricsRegistry) is the newer, OTel-based, exported-to-a-collector path, gated bytelemetry.*settings. Node stats (_nodes/stats) is the built-in, always-on, in-cluster path viaWriteable/ToXContent. A new metric goes in one or the other depending on who consumes it.
Common bugs and symptoms
| Symptom | Likely cause | First tool |
|---|---|---|
| One node pinned at 100% CPU | a hot query/agg, or a tight loop | _nodes/hot_threads?type=cpu |
| A specific query is slow, others fine | expensive clause/collector/agg in that query | _search {"profile":true} |
| Latency creeping up cluster-wide | GC pauses, or page-cache cold after restart | jstat -gcutil / GC log; storage-engine |
| Request never returns | a stuck/runaway task | _tasks?detailed → cancel; then jstack |
429 rejected_execution | a fixed pool's queue is full (back-pressure) | _cat/thread_pool (threadpools) |
Node stops serving search, search pool pinned | blocking work submitted to the SEARCH fixed pool | jstack — find the blocked [search] threads |
| Cluster loses its cluster manager under load | an applier/listener blocked the applier thread | jstack on clusterApplierService |
CircuitBreakingException on an aggregation | the request breaker tripped (the agg is too big) | _nodes/stats/breaker; circuit-breakers |
OutOfMemoryError, heap full | retained fielddata / giant agg / leak | heap dump → MAT dominator tree |
| GC runs constantly, reclaims little | leak or undersized heap | GC log + heap dump |
| Wrong agg result only with concurrency on | non-associative reduce in a CollectorManager | TRACE + concurrent-segment-search |
| Test fails ~1 in 20 runs | a flaky test (ordering/timing/seed) | pin -Dtests.seed; stage-9-flaky-tests |
| It worked last release, broken now | a regression | git bisect 2.x..main |
Reading exercise
# 1. The built-in sampling profiler.
find server -name HotThreads.java
grep -n "type\|interval\|isIdleThread\|busiest" \
server/src/main/java/org/opensearch/action/admin/cluster/node/hotthreads/HotThreads.java
# 2. Task tracking and cancellation.
grep -n "isCancelled\|cancelTaskAndDescendants\|registerCancellable" \
server/src/main/java/org/opensearch/tasks/TaskManager.java
# 3. Slow logs.
grep -n "threshold\|SearchSlowLog\|reformat\|source" \
server/src/main/java/org/opensearch/index/SearchSlowLog.java
# 4. The telemetry interfaces.
grep -rn "interface Tracer\|interface Span\|interface MetricsRegistry\|interface Counter\|interface Histogram" \
libs/telemetry/src/main/java/org/opensearch/telemetry/
# 5. A live triage pass.
curl -s 'localhost:9200/_nodes/hot_threads?threads=5'
curl -s 'localhost:9200/_tasks?detailed&group_by=parents' | python3 -m json.tool
curl -s 'localhost:9200/_nodes/stats/breaker' | python3 -m json.tool
Answer:
- For each symptom — slow, stuck, OOM, wrong — name the first tool you reach for and why it's the cheapest one that narrows the problem.
- Read a
hot_threadsline: what does the thread name tell you, what doesN/10 snapshots sharingmean, and what doestype=blockvstype=cpuchange? - In a Profile API response, what is the difference between
build_scorer,next_doc, andscore, and why are the absolute numbers untrustworthy? - Why is
_tasksthe right first call for a stuck request, and what makes task cancellation cooperative? - Walk a heap-dump investigation in MAT: which view do you open first, and what does "retained size" in the dominator tree mean?
- Contrast the telemetry framework (
Tracer/MetricsRegistry) with the_nodes/statspath: which is exported to a collector, which is always-on, and where does a new metric go? - Describe a full
git bisectrun: whatgood/badmark, what the reproducer is, and what the payoff (the introducing PR) gives you.
Validation: prove you understand this
-
Given a node pinned at 100% CPU, produce the exact
hot_threadscall, read a stack, and name the pool and the suspected code path from the thread name + frames. -
Run one query with
"profile": true, point to the dominant breakdown field, and explain what it measures and why the absolute nanos are inflated. - Enable a search slow log, trip it, find the line, and explain why the threshold is per-shard.
-
Find a long-running task via
_tasks, cancel it, and explain why cancellation is cooperative. -
From a
jstackdump, identify aBLOCKEDthread, find the lock holder, and (in Lab DP3) read aFound one Java-level deadlocksummary. - Take a heap dump, open the dominator tree in MAT, and name the retained-memory culprit and why it's still reachable.
-
Distinguish a breaker trip (
_nodes/stats/breaker) from an OOM, and say which one means "the system protected itself." -
Add a
Counteror aSpanto a code path, build, and explain where it surfaces (OTLP collector vs_nodes/stats). -
Run a
git bisectfrom agoodtag to abadmainwith a pinned-seed reproducer and name the introducing PR.
The labs: DP1 hot_threads & Profile API · DP2 JFR & async-profiler · DP3 Heap & Thread Dumps · DP4 Reproduce & Bisect.