vep-perf-profiling

name

vep-perf-profiling

description

Profile the VEP annotation pipeline end-to-end and present a structured timing breakdown (pipeline stages, Lance variation/SIFT lookup, engine + transcript-engine stages) to find bottlenecks. Use this whenever the user wants to profile, benchmark, or get a performance/timing breakdown of vepyr annotation, the variation cache lookup, the VEP engine, or asks "where is the time going / what's the bottleneck" for chr-scale annotation — even if they don't say the word "profile". Also use after a cache-layout or encoding change to confirm lookup cost and that the pipeline is still engine-bound.

VEP performance profiling & breakdown

Real end-to-end profiling runs through the sibling vepyr repo against a chr-scale cache, not this repo's unit tests. The pipeline emits nested per-batch timers to stderr; this skill runs it single-threaded (so timings are attributable, not smeared across worker threads) and turns the raw stderr into a clean breakdown.

Background: see the vep-profiling-setup memory and [[vep-annotation-bottlenecks]].

1. Run it (single-thread, all profile levels)

Pin threads to 1 so each stage's time is real, not overlapped. Enable every profile level. --skip-compare keeps it focused on timing (drop it only when you also want a parity check).

cd /Users/mwiewior/research/git/vepyr/e2e-testing/scripts
LANCE_CPU_THREADS=1 LANCE_IO_THREADS=1 RAYON_NUM_THREADS=1 \
VEP_PROFILE=1 VEP_ENGINE_PROFILE=1 VEP_TX_ENGINE_PROFILE=1 VEP_ENGINE_PROFILE_HGVSC=1 VEP_LANCE_PROFILE=1 \
  env -u VIRTUAL_ENV -u CONDA_PREFIX uv run python run_annotation_fast.py \
  chr1 --cache merged --forks 0 --force --backend lance --skip-compare \
  >/tmp/prof.stdout 2>/tmp/prof.profile

Profile knobs (each prints to stderr, aggregated per batch):

• VEP_PROFILE → pipeline_profile (annotate/engine/lookup_wait/hydrate/context_*) + vcf_sink + concurrency_plan.
• VEP_LANCE_PROFILE → [vep-lance-profile] per-batch: variation_take, sift_key_take, dataset open, variation_resolve.
• VEP_ENGINE_PROFILE → per-batch engine stages (evaluate_prepared, colocated_fields, csq_format, collapse_pick_sort, …).
• VEP_TX_ENGINE_PROFILE → transcript-engine stages (tx_query_total, transcript_output_materialize, transcript_hgvsc, transcript_overlap_eval, …).
• VEP_ENGINE_PROFILE_HGVSC → extra HGVSc sub-timers (coord_map/simple_fast/fallback); 0 if off.

Note: the tqdm Done: N variants line is a display artifact under heavy stderr profiling — trust output_rows= in pipeline_profile for the real count.

2. Extract the breakdown

Run the script — it parses /tmp/prof.profile into the four sections.

bash <skill-dir>/scripts/breakdown.sh /tmp/prof.profile

It emits: pipeline stage line, per-event Lance lookup totals + variation_take per-batch distribution, the full engine stage list, and the full transcript-engine stage list (each summed across all batches, sorted by time).

3. Present it

Use this structure (scale the tables to what's interesting). The goal is to show where the wall time goes and whether the pipeline is engine-bound or lookup-bound — that's the decision the breakdown exists to support.

## Pipeline (VEP_PROFILE)
annotate / engine / lookup_wait / hydrate / context_load

## Lance lookup (VEP_LANCE_PROFILE)
table: event | n | total | (variation_take per-batch min/median/mean/max)

## Engine — top level (VEP_ENGINE_PROFILE), additive
evaluate_prepared (the transcript-engine call), colocated_fields, csq_format, collapse_pick_sort, ...

## Transcript engine — inside evaluate_prepared (VEP_TX_ENGINE_PROFILE), nested
tx_query_total -> transcript_output_materialize / transcript_hgvsc (coord_map/simple_fast/fallback)
                  / transcript_overlap_eval (splice_terms) / position_fields / ...

## Reading it
- engine-bound? (engine / wall). Lookup the bottleneck? (lookup_wait vs engine).
- name the top 3-4 stages to target if optimizing.

Key interpretation rules (so the numbers aren't just dumped)

• evaluate_prepared ≈ tx_query_total — the top-level engine umbrella is the transcript engine; don't double-count them as separate costs. Engine top-level stages (evaluate_prepared, colocated_fields, csq_format, collapse_pick_sort, hgvs_shift) are additive; the tx-engine stages are nested inside evaluate_prepared.
• Lookup is usually not the bottleneck. variation_take may be several seconds of CPU, but it overlaps engine work on tokio workers — the real cost the engine pays is lookup_wait (typically ~1 s). If lookup_wait ≪ engine, the pipeline is engine-bound and lookup/encoding changes won't move the end-to-end number. Say so explicitly.
• This is the canonical profile: engine-bound (~60% of wall), dominated by transcript_output_materialize, transcript_hgvsc, colocated_fields, csq_format.

When comparing two cache layouts / encodings

Run the profile on each and compare variation_take (total + per-batch), lookup_wait, engine, and AF/dataset on-disk size. For raw read-amplification (bytes read, IOPS) — which VEP_LANCE_PROFILE does NOT give — use the Lance sandbox take-batches-bench against captured row_ids instead; that's a separate read-amp measurement, not part of this timing skill.