Performance Tracing & Bottleneck Analysis

HeliosDB Full ships with a built-in, zero-cost-when-disabled performance tracing system that instruments every layer of the database — from SQL parsing through storage I/O. Use it to pinpoint bottlenecks during performance tests, diagnose slow queries, and generate production-grade reports without external tooling.

Key Differences from Nano/Lite

Capability	Nano	Lite	Full
Granularity	Per-query phases	Per-query phases	Per-operation across 8 components
Span count	~8 phase types	~6 phase types	57 instrumented operations
Overhead when disabled	Branch check per query	`Option<QueryTrace>` check	Single atomic load (`AtomicBool`)
Overhead when enabled	~1-2us per query	~1-2us per query	~50ns per span (lock-free)
Percentiles	None	avg/p50/p95/p99	min/avg/p50/p95/p99 per operation
Hierarchical spans	No	No	Yes (parent-child relationships)
Component breakdown	No	No	Yes (8 components, % of session)
Output formats	Structured log events	Text report	Text report + JSON + programmatic API
Thread safety	Single-threaded	Single-threaded	Lock-free DashMap + thread-local stacks
SQL interface	`RUST_LOG` env var	`SET helios.trace_queries`	Programmatic API (see below)

Architecture

                    PerfTracer (global singleton)
                    ├── enabled: AtomicBool          ← zero-cost gate
                    ├── next_span_id: AtomicU64      ← lock-free ID generator
                    ├── completed: DashMap            ← all finished spans
                    └── aggregated: DashMap           ← running per-op statistics

 Thread 1                Thread 2                Thread 3
 ┌─────────────┐        ┌─────────────┐        ┌─────────────┐
 │ SPAN_STACK  │        │ SPAN_STACK  │        │ SPAN_STACK  │
 │ (thread-    │        │ (thread-    │        │ (thread-    │
 │  local)     │        │  local)     │        │  local)     │
 └──────┬──────┘        └──────┬──────┘        └──────┬──────┘
        │ drop guard           │ drop guard           │ drop guard
        └──────────────────────┴──────────────────────┘
                               │
                    ┌──────────▼──────────┐
                    │   DashMap shard N   │  ← lock-free aggregation
                    └─────────────────────┘

Zero-cost when disabled: Every perf_span! macro call starts with self.enabled.load(Ordering::Acquire). When tracing is off, this is a single CPU instruction (no branch misprediction after warmup) and the RAII guard stores span_id = 0, making Drop a no-op.

Lock-free when enabled: Each thread maintains its own span stack (thread_local!). On span completion, timing data is inserted into a DashMap (sharded concurrent hash map) — no global mutex, no contention between threads.

Quick Start

Rust API (Recommended)

use heliosdb_common::perf_tracer::{PerfTracer, Component};
use heliosdb_common::perf_span;

// 1. Enable tracing (resets previous data, starts session clock)
PerfTracer::global().enable();

// 2. Run your workload
//    All instrumented operations automatically record timing spans.
//    (execute queries, run benchmarks, etc.)

// 3. Generate the bottleneck report
let report = PerfTracer::global().generate_report();

// Human-readable text report
println!("{}", report.to_text());

// Machine-readable JSON (for dashboards, CI pipelines)
let json = report.to_json();
println!("{}", serde_json::to_string_pretty(&json).unwrap());

// 4. Disable tracing (returns to zero overhead)
PerfTracer::global().disable();

One-Liner for Quick Profiling

// Wrap any code block with enable/disable
PerfTracer::global().enable();
run_benchmark();
let report = PerfTracer::global().generate_report();
println!("{}", report.to_text());
PerfTracer::global().disable();

Instrumented Operations

Every operation below is automatically traced when the PerfTracer is enabled. No code changes needed — the spans are already wired into the hot paths.

Protocol Layer (10 spans)

Operation	Description	File
`sql_parse`	SQL text to AST	`heliosdb-protocols/src/postgres/sql_parser.rs`
`handle_query`	Full query lifecycle (top-level)	`heliosdb-protocols/src/postgres/handler.rs`
`execute_select`	SELECT execution	`heliosdb-protocols/src/postgres/handler.rs`
`execute_insert`	INSERT execution	`heliosdb-protocols/src/postgres/handler.rs`
`execute_update`	UPDATE execution	`heliosdb-protocols/src/postgres/handler.rs`
`execute_delete`	DELETE execution	`heliosdb-protocols/src/postgres/handler.rs`
`execute_create_table`	DDL CREATE TABLE	`heliosdb-protocols/src/postgres/handler.rs`
`execute_create_function`	DDL CREATE FUNCTION	`heliosdb-protocols/src/postgres/handler.rs`
`execute_call_procedure`	Stored procedure call	`heliosdb-protocols/src/postgres/handler.rs`
`execute_create_trigger`	DDL CREATE TRIGGER	`heliosdb-protocols/src/postgres/handler.rs`

Compute Layer (9 spans)

Operation	Description	File
`execute_plan`	Full query plan execution	`heliosdb-compute/src/executor/query_executor.rs`
`table_scan`	Sequential table scan	`heliosdb-compute/src/executor/query_executor.rs`
`index_scan`	Index-based lookup	`heliosdb-compute/src/executor/query_executor.rs`
`filter`	Predicate evaluation	`heliosdb-compute/src/executor/query_executor.rs`
`project`	Column projection	`heliosdb-compute/src/executor/query_executor.rs`
`hash_join`	Hash join build + probe	`heliosdb-compute/src/executor/query_executor.rs`
`aggregate`	GROUP BY / aggregation	`heliosdb-compute/src/executor/query_executor.rs`
`sort`	ORDER BY sort	`heliosdb-compute/src/executor/query_executor.rs`
`window_function`	Window function evaluation	`heliosdb-compute/src/executor/query_executor.rs`

Optimizer Layer (2 spans)

Operation	Description	File
`optimize_query`	Full optimization pass	`heliosdb-compute/src/optimizer_legacy.rs`
`cost_estimation`	Cost model evaluation	`heliosdb-compute/src/optimizer_legacy.rs`

Parallel Execution (2 spans)

Operation	Description	File
`parallel_execute`	Work-stealing parallel execution	`heliosdb-compute/src/parallel_query.rs`
`partition_data`	Data partitioning for parallelism	`heliosdb-compute/src/parallel_query.rs`

Storage Layer (9 spans)

Operation	Description	File
`lsm_put`	LSM tree write (memtable insert)	`heliosdb-storage/src/lsm.rs`
`lsm_get`	LSM tree point read	`heliosdb-storage/src/lsm.rs`
`lsm_delete`	LSM tree delete (tombstone write)	`heliosdb-storage/src/lsm.rs`
`lsm_scan`	LSM tree range scan (k-way merge)	`heliosdb-storage/src/lsm.rs`
`wal_write`	Write-ahead log entry	`heliosdb-storage/src/lsm.rs`
`memtable_flush`	Memtable flush to SSTable	`heliosdb-storage/src/lsm.rs`
`compaction`	SSTable level compaction	`heliosdb-storage/src/lsm.rs`
`sstable_write`	SSTable file creation	`heliosdb-storage/src/sstable.rs`
`sstable_get`	SSTable point lookup (bloom + index)	`heliosdb-storage/src/sstable.rs`
`sstable_scan`	SSTable range scan	`heliosdb-storage/src/sstable.rs`

Cluster Layer (7 spans)

Operation	Description	File
`raft_append`	Raft log append	`heliosdb-cluster/src/consensus/mod.rs`, `log.rs`
`raft_election`	Raft leader election	`heliosdb-cluster/src/consensus/mod.rs`, `raft_node.rs`
`raft_commit`	Raft entry commit	`heliosdb-cluster/src/consensus/mod.rs`
`cache_fusion_lookup`	Cache fusion remote lookup	`heliosdb-cluster/src/cache_fusion.rs`
`cache_fusion_transfer`	Cache fusion block transfer	`heliosdb-cluster/src/cache_fusion.rs`
`distributed_scan`	Distributed smart scan coordination	`heliosdb-storage/src/distributed_smart_scan.rs`

Metadata Layer (2 operation types, 8 spans)

Operation	Description	File
`schema_lookup`	Schema/catalog resolution	`heliosdb-metadata/src/schema_service.rs`, `raft_service.rs`
`ddl_execute`	DDL operation execution	`heliosdb-metadata/src/schema_service.rs`, `raft_service.rs`

Understanding the Report

Sample Output

+======================================================================+
|              HeliosDB Performance Bottleneck Report                   |
+======================================================================+

Session Duration: 12.45s  |  Total Spans: 45,230

-- Component Breakdown ----------------------------------------------------
Component      Total Time      Spans   % Sess
--------------------------------------------------------------
Storage           8.92s       22,100    71.6%
Compute           2.34s       11,500    18.8%
Protocol          0.89s        5,600     7.1%
Optimizer         0.21s        5,600     1.7%
Metadata          0.09s          430     0.7%

-- Top Bottlenecks (by total time) ----------------------------------------
Component    Operation                       Total     Count        Avg        P99  % Sess
------------------------------------------------------------------------------------------
Storage      lsm_scan                        5.12s      2800      1.8ms     12.3ms   41.1%
Storage      sstable_scan                    2.45s      8400      291us      1.2ms   19.7%
Compute      hash_join                       1.23s       450      2.7ms     15.1ms    9.9%
Compute      sort                            0.67s       320      2.1ms      8.4ms    5.4%
Protocol     execute_select                  0.56s      2800      200us      1.1ms    4.5%
Storage      lsm_put                         0.45s      5000       90us      450us    3.6%
Storage      memtable_flush                  0.38s        12     31.7ms     45.2ms    3.1%
Compute      aggregate                       0.34s       280      1.2ms      4.5ms    2.7%
Optimizer    optimize_query                  0.21s      5600       38us      120us    1.7%
Protocol     sql_parse                       0.18s      5600       32us       95us    1.4%

-- All Operations ---------------------------------------------------------
Component    Operation                      Count      Total        Min        Avg        P95        P99
---------------------------------------------------------------------------------------------------------
Storage      lsm_scan                        2800      5.12s      120us      1.8ms      8.5ms     12.3ms
Storage      sstable_scan                    8400      2.45s       15us      291us      850us      1.2ms
...

How to Read It

Component Breakdown shows where time is spent at the macro level. In the example above, 71.6% of traced time is in Storage — typical for I/O-bound workloads. If Optimizer or Protocol dominate, investigate complex queries or parsing overhead.

Top Bottlenecks ranks individual operations by total cumulative time. The most impactful optimization target is the #1 bottleneck. Key metrics:

Total: Cumulative wall time across all invocations. The primary ranking metric.
Count: Number of times this operation was called. High count with low avg = many small operations. Low count with high avg = few expensive operations.
Avg: Average duration per invocation.
P99: 99th percentile — the “worst case” that 1% of invocations exceed. If P99 >> Avg, you have tail latency outliers.
% Sess: Percentage of the total session duration. Tells you the maximum speedup you’d get by eliminating this bottleneck entirely (Amdahl’s law).

All Operations provides the full statistical breakdown for every traced operation.

Performance Testing Workflow

1. Baseline Measurement

use heliosdb_common::perf_tracer::PerfTracer;

// Reset and enable
PerfTracer::global().enable();

// Run baseline workload
run_oltp_benchmark(1000); // e.g., 1000 transactions

// Capture baseline report
let baseline = PerfTracer::global().generate_report();
let baseline_json = baseline.to_json();
println!("=== BASELINE ===\n{}", baseline.to_text());
PerfTracer::global().disable();

2. Make Changes

// Add an index, tune a config parameter, change a query, etc.

3. Compare

PerfTracer::global().enable();
run_oltp_benchmark(1000); // same workload
let after = PerfTracer::global().generate_report();
println!("=== AFTER CHANGE ===\n{}", after.to_text());
PerfTracer::global().disable();

// Programmatic comparison
let b = &baseline_json["bottlenecks"][0];
let a = &after.to_json()["bottlenecks"][0];
println!(
    "Top bottleneck: {} -> {} (was {}us, now {}us)",
    b["operation"], a["operation"],
    b["avg_duration_us"], a["avg_duration_us"],
);

4. Drill Into Specific Operations

let report = PerfTracer::global().generate_report();

// Find all storage operations slower than 1ms average
for op in &report.operations {
    if op.component == heliosdb_common::perf_tracer::Component::Storage
        && op.avg_duration > std::time::Duration::from_millis(1)
    {
        println!(
            "SLOW: {} — avg {:?}, p99 {:?}, count {}",
            op.operation, op.avg_duration, op.p99_duration, op.count
        );
    }
}

Adding Custom Spans

Instrument your own code with the perf_span! macro. Spans nest automatically via the thread-local stack.

use heliosdb_common::perf_tracer::Component;
use heliosdb_common::perf_span;

fn process_batch(batch: &[Row]) {
    // Simple span (operation name only)
    let _span = perf_span!(Component::Compute, "process_batch");

    for row in batch {
        // Span with key-value attributes (for debugging, not aggregation)
        let _row_span = perf_span!(
            Component::Compute, "process_row",
            "batch_size" => batch.len(),
            "row_key" => row.key
        );
        // ... processing ...
        // _row_span records timing on drop
    }
    // _span records timing on drop (includes all child spans)
}

Span Nesting

Spans automatically form parent-child relationships within each thread:

{
    let _outer = perf_span!(Component::Protocol, "handle_query");
    {
        let _parse = perf_span!(Component::Protocol, "sql_parse");
        // parse_span.parent_id == outer_span.span_id
    }
    {
        let _optimize = perf_span!(Component::Optimizer, "optimize_query");
        // optimize_span.parent_id == outer_span.span_id
    }
    {
        let _exec = perf_span!(Component::Compute, "execute_plan");
        {
            let _scan = perf_span!(Component::Storage, "lsm_scan");
            // scan_span.parent_id == exec_span.span_id
            // scan_span.depth == 2
        }
    }
}

Component Selection

Choose the component that owns the operation:

Component	Use For
`Component::Storage`	Anything touching disk, memtable, WAL, SSTables, compaction
`Component::Compute`	Query execution, joins, sorts, aggregation, expression evaluation
`Component::Optimizer`	Query planning, cost estimation, rule application
`Component::Protocol`	SQL parsing, wire protocol handling, result serialization
`Component::Network`	Connection management, transport, RPC
`Component::Cluster`	Raft consensus, replication, distributed coordination
`Component::Cache`	Block cache, query cache, tiered cache lookups
`Component::Metadata`	Schema catalog, DDL operations

JSON Output for CI/Dashboards

The JSON report format is designed for automated analysis:

{
  "session_duration_us": 12450000,
  "total_spans": 45230,
  "components": [
    {
      "component": "Storage",
      "total_duration_us": 8920000,
      "span_count": 22100,
      "pct_of_session": 71.6
    }
  ],
  "bottlenecks": [
    {
      "component": "Storage",
      "operation": "lsm_scan",
      "total_duration_us": 5120000,
      "count": 2800,
      "avg_duration_us": 1828,
      "p99_duration_us": 12300,
      "pct_of_session": 41.1
    }
  ],
  "operations": [
    {
      "component": "Storage",
      "operation": "lsm_scan",
      "count": 2800,
      "total_duration_us": 5120000,
      "min_duration_us": 120,
      "avg_duration_us": 1828,
      "p50_duration_us": 1450,
      "p95_duration_us": 8500,
      "p99_duration_us": 12300
    }
  ]
}

CI Integration Example

let report = PerfTracer::global().generate_report();
let json = report.to_json();

// Fail CI if any operation's p99 exceeds threshold
for op in json["operations"].as_array().unwrap() {
    let p99 = op["p99_duration_us"].as_u64().unwrap();
    let name = op["operation"].as_str().unwrap();
    if p99 > 50_000 { // 50ms threshold
        panic!("PERF REGRESSION: {} p99 = {}us (threshold: 50000us)", name, p99);
    }
}

Interpreting Common Patterns

Pattern	Likely Cause	Action
Storage > 70% of session	I/O-bound workload	Check `lsm_scan` and `sstable_scan` counts; add indexes; tune compaction
`lsm_scan` P99 >> Avg	Tail latency from scanning many SSTables	Run compaction; check level count
`memtable_flush` high avg	Large memtable or slow disk	Increase flush parallelism; check I/O bandwidth
`compaction` high total	Background compaction stealing I/O	Tune compaction rate limiter; schedule off-peak
`hash_join` dominates Compute	Large hash tables for joins	Check join order; add join indexes; increase memory
`sort` high total	Many ORDER BY without index	Add covering indexes for sorted access patterns
`optimize_query` > 10% session	Complex queries trigger expensive planning	Simplify queries; use prepared statements
`sql_parse` high total	Very long SQL strings or many distinct queries	Use parameterized queries; batch operations
`wal_write` P99 high	WAL fsync latency spikes	Check disk IOPS; enable group commit (`DirectIoWal`)
`raft_append` high in cluster	Consensus latency between nodes	Check network latency; reduce replication factor for reads
`cache_fusion_transfer` high	Remote cache misses	Co-locate hot data; increase local cache size
Optimizer cost low but Compute high	Good plans but slow execution	Focus on storage I/O and compute optimization
Protocol > 20% session	Parsing or serialization overhead	Use prepared statements; reduce result set size

Overhead Characteristics

Disabled (Default) — Zero Cost

perf_span!() call:
  1. AtomicBool::load(Acquire)     ~1ns   (single CPU instruction)
  2. Branch: span_id == 0 → skip   ~0ns   (predicted after warmup)
  3. Drop: span_id == 0 → no-op    ~0ns

Total overhead per span: ~1ns (unmeasurable in practice)

The compiler inlines the #[inline(always)] is_enabled() check. After branch predictor warmup, the disabled path adds zero measurable overhead — verified by benchmarking with and without instrumentation.

Enabled — Low Overhead

perf_span!() call:
  1. AtomicU64::fetch_add(Relaxed)  ~5ns   (span ID)
  2. Instant::now()                 ~25ns  (clock read)
  3. thread_local push              ~10ns  (stack push)

Drop (span completion):
  4. Instant::elapsed()             ~25ns  (clock read)
  5. thread_local pop               ~10ns  (stack pop)
  6. DashMap::entry().record()      ~30ns  (lock-free insert)

Total overhead per span: ~100ns when enabled

For a workload producing 10,000 spans/second, that’s ~1ms of tracing overhead per second (0.1%). For 100,000 spans/second, ~10ms/second (1%). This is acceptable for staging and targeted production debugging.

Memory Usage

Per completed span: ~200 bytes (component, operation string, duration, attributes, IDs)
Per aggregated operation: ~500 bytes + 8 bytes per recorded duration
10,000 spans session: ~2MB memory
100,000 spans session: ~20MB memory

Call PerfTracer::global().reset() between test runs to free accumulated data.

API Reference

`PerfTracer`

// Get the global singleton
PerfTracer::global() -> &'static PerfTracer

// Lifecycle
tracer.enable()              // Enable + reset + start session clock
tracer.disable()             // Disable (spans become no-ops)
tracer.is_enabled() -> bool  // Fast check (atomic load)
tracer.reset()               // Clear all data without changing enabled state

// Span creation
tracer.begin_span(component, operation, attributes) -> PerfSpanGuard

// Reporting
tracer.generate_report() -> PerfReport
tracer.span_count() -> usize

`PerfReport`

report.to_text() -> String              // Human-readable table
report.to_json() -> serde_json::Value   // Machine-readable JSON

// Fields
report.session_duration: Duration
report.total_spans: u64
report.operations: Vec<OperationStats>      // All ops, sorted by total time desc
report.component_summary: Vec<ComponentSummary>  // Per-component aggregation
report.bottlenecks: Vec<Bottleneck>         // Top 10 by total time
report.spans: Vec<CompletedSpan>            // All individual spans (for analysis)

`perf_span!` Macro

// Simple span (no attributes)
let _span = perf_span!(Component::Storage, "operation_name");

// Span with key-value attributes
let _span = perf_span!(Component::Storage, "operation_name",
    "key1" => value1,
    "key2" => value2
);

// The guard (_span) MUST be bound to a variable.
// If not bound, it drops immediately and records zero duration.
// WRONG: perf_span!(Component::Storage, "op");  // drops immediately!
// RIGHT: let _span = perf_span!(Component::Storage, "op");

Comparison with External Tracing Tools

Feature	PerfTracer (built-in)	`tracing` crate	Jaeger/OpenTelemetry
Setup	Zero config	Subscriber setup	Agent + collector infrastructure
Overhead disabled	~1ns (atomic load)	~5ns (subscriber check)	N/A (not embedded)
Overhead enabled	~100ns/span	~200ns/span	~1-5us/span (network export)
Percentile stats	Built-in (p50/p95/p99)	Requires aggregator	Requires backend query
Bottleneck ranking	Automatic	Manual analysis	Manual query
Thread safety	Lock-free (DashMap)	Layer-dependent	Async export
Distributed tracing	Span hierarchy only	Full distributed	Full distributed
Production use	Targeted debugging	Always-on possible	Always-on recommended

Use PerfTracer for: Performance testing, benchmarking, targeted bottleneck analysis, CI regression checks.

Use tracing crate for: Always-on structured logging, distributed request tracing, log aggregation.

Use OpenTelemetry for: Multi-service distributed tracing, production observability, SLO monitoring.

PerfTracer is complementary to these tools — it provides instant, zero-dependency bottleneck analysis without any infrastructure setup.

Performance Tracing & Bottleneck Analysis

Performance Tracing & Bottleneck Analysis

Key Differences from Nano/Lite

Architecture

Quick Start

Rust API (Recommended)

One-Liner for Quick Profiling

Instrumented Operations

Protocol Layer (10 spans)

Compute Layer (9 spans)

Optimizer Layer (2 spans)

Parallel Execution (2 spans)

Storage Layer (9 spans)

Cluster Layer (7 spans)

Metadata Layer (2 operation types, 8 spans)

Understanding the Report

Sample Output

How to Read It

Performance Testing Workflow

1. Baseline Measurement

2. Make Changes

3. Compare

4. Drill Into Specific Operations

Adding Custom Spans

Span Nesting

Component Selection

JSON Output for CI/Dashboards

CI Integration Example

Interpreting Common Patterns

Overhead Characteristics

Disabled (Default) — Zero Cost

Enabled — Low Overhead

Memory Usage

API Reference

PerfTracer

PerfReport

perf_span! Macro

Comparison with External Tracing Tools

`PerfTracer`

`PerfReport`

`perf_span!` Macro