---
title: "Performance Tracing & Bottleneck Analysis"
---

# 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

```sql
-- 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)`:

```sql
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:

```sql
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

```sql
-- 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)

```sql
CREATE INDEX idx_orders_customer ON orders (customer_id);
```

### 3. Compare

```sql
-- 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

```sql
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;
```

## Automated Performance Tests

Tracing is controlled with SQL, so a test harness can drive it over the PostgreSQL wire with
any driver, or from a script with `psql`:

```sql
-- Enable tracing for the session
SET helios.trace_queries = on;

-- Run the workload ...
SELECT * FROM users WHERE id = 42;

-- Per-phase report and global counters
SHOW helios.trace_report;
SHOW helios.perf_summary;

-- Reset before the next test
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)**: Effectively zero cost: a single branch per query.
- **Enabled**: ~1-2μs overhead per query for timing. The ring buffer holds up to 1,000 traces before evicting oldest entries.
- **Global counters**: 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.