Performance Tracing & Bottleneck Analysis

HeliosDB provides built-in query tracing that captures per-query lifecycle timing across every phase of execution. Use it to identify bottlenecks during performance tests, debug slow queries, and understand how the optimizer affects your workload.

Quick Start

-- Enable tracing for this session
SET helios.trace_queries = on;

-- Run your workload
SELECT * FROM orders WHERE customer_id = 42;
SELECT o.id, c.name FROM orders o JOIN customers c ON o.customer_id = c.id WHERE o.total > 100;
INSERT INTO logs (message) VALUES ('test');

-- View the bottleneck report
SHOW helios.trace_report;

Tracing Commands Reference

Command	Description
`SET helios.trace_queries = on`	Enable per-query tracing for this session
`SET helios.trace_queries = off`	Disable tracing
`SHOW helios.trace_report`	Consolidated bottleneck report with percentile stats
`SHOW helios.perf_summary`	Global atomic counter summary (all sessions)
`SHOW helios.trace_reset`	Clear all trace data and reset global counters
`EXPLAIN (TRACE) <query>`	One-shot per-phase breakdown for a single query

Understanding the Bottleneck Report

SHOW helios.trace_report produces a report like this:

=== Query Trace Bottleneck Report ===
Traced queries: 150

Phase Breakdown (avg / p50 / p95 / p99):
  Parse:    45μs / 38μs / 112μs / 230μs
  Plan:     120μs / 95μs / 340μs / 580μs
  Optimize: 85μs / 72μs / 210μs / 450μs
  Execute:  2.35ms / 1.80ms / 8.50ms / 15.20ms
  Total:    2.60ms / 2.01ms / 9.16ms / 16.46ms

Bottleneck phase: execute

Top 5 Slowest Queries:
  1. 15.20ms — SELECT * FROM orders WHERE total > 100 ORDER BY cre... (1250 rows)
  2. 12.80ms — SELECT o.id, c.name FROM orders o JOIN customers c O... (890 rows)
  3. 9.50ms — SELECT count(*) FROM orders GROUP BY status (5 rows)
  4. 8.20ms — UPDATE orders SET status = 'shipped' WHERE id IN (SEL... (0 rows)
  5. 7.10ms — SELECT * FROM customers WHERE name LIKE '%smith%' (42 rows)

Optimizer Rules Applied:
  PredicatePushdown: 120 times
  ConstantFolding: 95 times
  ProjectionPushdown: 80 times
  JoinReordering: 45 times

What each section tells you

Phase Breakdown — Averages and percentiles (p50/p95/p99) for each query phase:

Parse: SQL text to AST. High times here suggest overly complex SQL syntax or very long query strings.
Plan: AST to logical plan (schema resolution, type checking). High times indicate complex joins, many subqueries, or catalog lookup overhead.
Optimize: Logical plan transformations (predicate pushdown, join reordering, etc.). High times mean the optimizer is doing significant work — usually a good sign unless it’s disproportionate.
Execute: Physical execution (scanning, filtering, joining, sorting). This is typically the dominant phase and where most tuning effort should focus.

Bottleneck phase — The phase consuming the most time on average. If this is anything other than “execute”, investigate why planning/parsing is expensive.

Top 5 Slowest Queries — The queries with the highest total wall time. Focus optimization efforts here.

Optimizer Rules Applied — How frequently each optimizer rule fires across your workload. Useful for understanding whether the optimizer is working effectively.

EXPLAIN (TRACE) — Single Query Analysis

For debugging a specific query, use EXPLAIN (TRACE):

EXPLAIN (TRACE) SELECT o.id, c.name, o.total
FROM orders o
JOIN customers c ON o.customer_id = c.id
WHERE o.total > 100
ORDER BY o.total DESC
LIMIT 10;

Output includes the standard EXPLAIN plan plus per-phase timing:

Limit (rows=10)
  Sort (key=orders.total DESC)
    HashJoin (orders.customer_id = customers.id)
      Filter (orders.total > 100)
        Scan: orders
      Scan: customers

--- Query Trace ---
Execution time: 3.45ms
Result rows: 10

Combine with ANALYZE for operator-level detail:

EXPLAIN (ANALYZE, TRACE) SELECT * FROM orders WHERE status = 'pending';

Global Performance Summary

SHOW helios.perf_summary shows cumulative atomic counters across all sessions:

=== Performance Summary ===
Query Phases (avg μs):
  Parse: 42μs | Plan: 115μs | Exec: 2350μs
Storage (avg μs):
  Read: 15μs | Write: 180μs | Commit: 520μs
Cache: 87.3% hit rate
Totals: 15000 queries, 45000 reads, 3000 writes

This is useful for high-level system health. The counters accumulate from server start (or last reset) and include all sessions, not just the current one.

Performance Testing Workflow

1. Baseline measurement

-- Reset everything
SHOW helios.trace_reset;

-- Enable tracing
SET helios.trace_queries = on;

-- Run your baseline workload
-- (application queries, benchmark script, etc.)

-- Capture baseline
SHOW helios.trace_report;

2. Make changes (add index, tune config, modify query)

CREATE INDEX idx_orders_customer ON orders (customer_id);

3. Compare

-- Reset and re-run
SHOW helios.trace_reset;

-- Run the same workload again

-- Compare against baseline
SHOW helios.trace_report;

4. Drill into specific slow queries

EXPLAIN (ANALYZE, TRACE) SELECT o.id, c.name
FROM orders o JOIN customers c ON o.customer_id = c.id
WHERE o.status = 'pending' AND o.total > 500;

Programmatic Access (Rust API)

The tracing system is available through the Rust API for automated performance testing:

use heliosdb_lite::EmbeddedDatabase;

let db = EmbeddedDatabase::new_in_memory()?;

// Enable tracing
db.query("SET helios.trace_queries = on", &[])?;

// Run workload
for i in 0..1000 {
    db.query("SELECT * FROM users WHERE id = $1", &[])?;
}

// Get report
let report = db.query("SHOW helios.trace_report", &[])?;
println!("{}", report[0].values[0]);

// Get global counters
let summary = db.query("SHOW helios.perf_summary", &[])?;
println!("{}", summary[0].values[0]);

// Reset for next test
db.query("SHOW helios.trace_reset", &[])?;

Interpreting Common Patterns

Pattern	Likely Cause	Action
Execute p99 >> p50	A few queries scanning large tables	Add indexes, check `EXPLAIN ANALYZE` on the outliers
Plan time > Execute time	Complex query planning (many joins, subqueries)	Simplify queries, use prepared statements
Optimize time high	Many optimizer rules firing	Usually fine — means the optimizer is active
Parse time high	Very long SQL strings or many statements	Use prepared statements, parameterized queries
Low cache hit rate	Working set exceeds cache	Increase cache size or optimize access patterns

Overhead

Disabled (default): Zero cost. The Option<QueryTrace> check compiles to a single branch.
Enabled: ~1-2μs overhead per query for timing. The ring buffer holds up to 1,000 traces before evicting oldest entries.
Global PerfCounters: Always active, using lock-free atomic increments (~5ns per counter update).

Tracing is designed for use in staging, pre-production performance tests, and targeted production debugging. For always-on production monitoring, use SHOW helios.perf_summary which has negligible overhead.