starrocks/starrocks-debug-skills/query

Query Troubleshooting

Investigation guide for query hangs, slow queries, profile analysis, scan performance, join performance, and bug localization.

Three root causes account for the vast majority of cases:

• Cause A — Network/connection issue (TCP backlog, accept queue saturation)
• Cause B — FE lock / GC blocking (deadlock, full GC pause)
• Cause C — Scan bottleneck (data skew, no predicate pushdown, rowset accumulation)
• Cause D — Join bottleneck (broadcast OOM, missing statistics)
• Cause E — Bug localization (wrong results, executor crash)

Metric Taxonomy — Read This First

Before using any metrics, understand the two-layer observability structure:

FE-side metrics

BE-side metrics

How to retrieve metrics

Option 1 — FE audit log (historical)

# Find slowest queries by QueryTime
grep 'slow_query' fe.audit.log | cut -d '=' -f 6 | cut -d '|' -f 1 | sort -g | tail -20
 
# Find high-memory queries
python3 scripts/analyze_logs.py "2025-04-15 00:00:00" "2025-04-15 01:00:00" "MemCostBytes" 3 fe.audit.log
 
# Audit log field order (pipe-delimited):
# Timestamp | ClientIP | User | QueryId | QueryTime | ScanBytes | ScanRows | ReturnRows | StmtId | IsQuery | FeIp | Stmt | Digest | PlanCpuCost | PlanMemCost | PendingTimeMs | MemCostBytes

Option 2 — SQL (live, in-flight queries)

-- View all running queries with resource usage
SHOW PROC '/current_queries';
-- Key columns: QueryId, ConnectionId, Database, User, ScanRows, ProcessRows, ExecTime, MemUsageBytes
 
-- Kill a specific query
KILL QUERY '<connection_id>';

Option 3 — Profile (per-query operator breakdown)

-- Enable profile collection before running the query
SET is_report_success = true;
-- Run query, then view profile:
-- FE HTTP UI: http://<fe_ip>:8030 → Queries → Profile
 
-- Or list recent profiles and analyze
SHOW PROFILELIST;
ANALYZE PROFILE FROM '<profile_id>';

Option 4 — BE compaction metrics (scan MERGE time signal)

# High cumulative score → rowset accumulation → slow scan MERGE phase
curl -s "http://<be_ip>:8040/metrics" | grep "tablet_cumulative_max_compaction_score"
 
# Loop all BEs
for be in 10.0.0.1 10.0.0.2 10.0.0.3; do
  echo "=== $be ==="
  curl -s "http://$be:8040/metrics" | grep "tablet_cumulative_max_compaction_score"
done

Key rules for interpretation:

1. Always start with fe.audit.log for historical slow queries — QueryTime shows end-to-end latency; correlate ScanBytes vs ReturnRows to spot pushdown failures.
2. SHOW PROC '/current_queries' gives live in-flight state; ExecTime is wall-clock elapsed — compare against query_timeout setting to judge urgency.
3. Profile OLAP_SCAN_NODE Active time variance across instances reveals data skew — one instance 10× slower than peers is the primary signal.
4. Profile MERGE time as a fraction of OLAP_SCAN_NODE Active indicates rowset accumulation — above 50% means compaction is lagging.
5. If fe.audit.log shows no entry for the query ID, the FE never received the request — go to Cause A (network/connection).

Query Issue Type Reference

Phase 1 — Confirm Query Is Problematic

Step 1.1 — Check if FE received the request

# Search for the query registration in FE log
grep "register query id" fe.log | grep "<query_id>"

• Found → FE received the request → proceed to Step 1.2
• Not found → FE never received it → Cause A signal → go to Phase 3, Cause A

Step 1.2 — Check live in-flight state

-- Is the query still running? How long?
SHOW PROC '/current_queries';
-- ExecTime vs query_timeout: if ExecTime > 80% of timeout, it will likely fail
-- MemUsageBytes growing rapidly → potential OOM → Cause D signal

Step 1.3 — Check audit log for historical pattern

# Did this query or similar queries consistently run slow?
grep "<query_id_prefix>" fe.audit.log | awk -F'|' '{print $5}'
# QueryTime column — multiple slow entries → structural problem, not transient
 
# Check if query even completed (vs hang / timeout)
grep "slow_query" fe.audit.log | tail -30

Phase 1 result → route by cause:

Phase 2 — Locate Bottleneck by Profile

Step 2.1 — Enable and collect profile

SET is_report_success = true;
-- Re-run the slow query
-- Then: http://<fe_ip>:8030 → Queries → Profile
-- Or:
SHOW PROFILELIST;
ANALYZE PROFILE FROM '<profile_id>';

Step 2.2 — Read OLAP_SCAN_NODE metrics

Key metrics in OLAP_SCAN_NODE:

Step 2.3 — Identify the bottleneck type

Scan bottleneck signals (→ Cause C):

MERGE time > 50% of OLAP_SCAN_NODE Active   → rowset accumulation
One instance Active >> peers (10x)           → data skew
PushdownPredicates = 0                       → predicate pushdown failed
ZoneMapIndexFilterRows = 0                   → index not effective

Join bottleneck signals (→ Cause D):

HASH_JOIN_NODE BuildTime high               → right table too large
HASH_JOIN_NODE BuildRows very large         → consider shuffle instead of broadcast
EXCHANGE_NODE time dominates                → large table broadcast
JoinRuntimeFilterEvaluate = 0              → no runtime filter applied

Step 2.4 — Profile time discrepancy

When total Profile time significantly exceeds BE Active time:

1. Check fe.warn.log for retry logs.
2. Primary Key model (older versions): lock acquisition timeout — look for gap between prepare and open.
3. Optimizer too slow — verify with explain; or jstack to see if stuck in plan generation.
4. Import lock interference — import holds DB lock, blocking query lock acquisition.
5. FE Full GC — check fe.gc.log timestamps.

Phase 3 — Take Action by Cause

Cause A — Network / Connection Issue

Confirm all match:

• No register query id entry in fe.log for the query
• netstat -s | grep TCPBacklogDrop shows non-zero and growing
• ss -lnt shows Recv-Q ≈ backlog limit on FE port 9030

Mechanism: When connection burst exceeds the OS TCP listen queue (controlled by somaxconn), new SYN packets are silently dropped. The FE ConnectProcessor never sees the connection and logs nothing. The client receives a connection timeout with no error from FE.

# Confirm backlog overflow
netstat -s | grep -i LISTEN
netstat -s | grep TCPBacklogDrop
cat /proc/sys/net/ipv4/tcp_abort_on_overflow

Fix:

• Set tcp_abort_on_overflow to 1 (returns RST instead of silent drop — easier to diagnose)
• Increase somaxconn (at least 1024)
• Adjust FE parameters: mysql_nio_backlog_num, http_backlog_num, thrift_backlog_num (must be ≥ somaxconn)
• Restart FE after parameter change

→ Go to Phase 4 to verify recovery

Cause B — FE Lock / GC Blocking

Confirm all match:

• register query id present in fe.log but query never dispatched to BE
• jstack <fe_pid> shows ConnectProcessor threads waiting on same lock object address
• OR fe.gc.log shows Full GC events aligned with the hang window

Mechanism (lock): Two query threads acquire FE DB locks in different orders, creating a circular wait. All subsequent queries needing either lock queue behind blocked threads. FE heartbeat stays alive but no fragments are dispatched.

Mechanism (GC): Full GC pauses the JVM for seconds or minutes, freezing all FE threads. All pending queries appear hung during the pause.

# Capture jstack (repeat 3x, 10 seconds apart)
jstack <fe_pid> > /tmp/fe_jstack_$(date +%s).log
 
# Look for ConnectProcessor threads waiting on same lock
grep -A 30 "ConnectProcessor" /tmp/fe_jstack_*.log
 
# Check GC log for Full GC during the hang window
grep "Full GC" fe.gc.log | tail -20

Action: capture multiple jstack dumps, then restart FE.

# Check if BE received the query (rules out FE-only issue)
grep "Prepare(): query_id=<target_query_id>" be.log

If BE received it → issue is on BE side → check pstack / execution thread pool (Step 1.6 in original guide).

→ Go to Phase 4 to verify recovery

Cause C — Scan Bottleneck

C1: Data Skew

Confirm all match:

• Profile shows one OLAP_SCAN_NODE instance Active time 10× higher than peers
• SHOW TABLET FROM <table> shows DataSize variance > 10× across tablets

Mechanism: Low-cardinality bucket key (e.g., status, region) concentrates majority of rows in one or few tablets. All queries on hot range land on one scan instance. BE CPU on hot node saturates; others idle. Query latency is dominated by the slowest straggler scan instance.