Files
doczyai-pipelines/documentation/PERFORMANCE_ANALYSIS_GUIDE.md
T

201 lines
8.8 KiB
Markdown
Raw Normal View History

# Performance Analysis Guide
## Overview
This guide explains the timing instrumentation added to the pipeline and how to interpret the results to identify bottlenecks and parallelization opportunities.
## Instrumented Components
### 1. Main Pipeline (`main.py`)
- **`read_constants`**: Loading configuration and constants
- **`read_input`**: Reading input files from S3 or local storage
- **`warm_prompt_caches`**: Pre-warming Claude prompt caches
- **`parallel_file_processing`**: Main parallel processing of all files (CRITICAL METRIC)
- **`concat_results`**: Concatenating all file results into final dataframes
- **`qc_qa_validation`**: Quality control and QA validation
- **`write_outputs`**: Writing final outputs to S3/local storage
- **`parent_child_mapping`**: Parent-child relationship mapping (if enabled)
### 2. Per-File Processing (`file_processing.py`)
Each file goes through these stages (tracked with `context=filename`):
- **`{filename}.preprocess`**: Text cleaning, splitting, header/footer detection
- **`{filename}.one_to_n_exhibit_chunking`**: Chunking document into exhibits
- **`{filename}.one_to_n_extraction`**: Extracting one-to-many relationships (parallel exhibits)
- **`{filename}.one_to_n_generate_reimb_ids`**: Generating reimbursement IDs
- **`{filename}.one_to_one_extraction`**: Extracting one-to-one fields (see below)
- **`{filename}.merge_one_to_one_into_one_to_n`**: Merging results
- **`{filename}.code_processing`**: Code breakout and grouper processing
- **`{filename}.postprocess`**: Final postprocessing and validation
- **`{filename}.write_individual`**: Writing individual file results
### 3. One-to-One Processing (`file_processing.py` -> `run_one_to_one_prompts`)
- **`{filename}.one_to_one.provider_info`**: Extracting TIN/NPI provider information
- **`{filename}.one_to_one.hybrid_smart_chunking`**: RAG-based field extraction (CRITICAL)
- **`{filename}.one_to_one.full_context`**: Full-context field extraction (fallback)
### 4. Hybrid Smart Chunking (RAG) (`hybrid_smart_chunking_funcs.py`)
This is often the bottleneck. Detailed timing:
- **`{filename}.hsc.setup`**: Setting up embeddings, reranker, and text splitter
- **`{filename}.hsc.preprocessing`**: Document preprocessing and chunking
- **`{filename}.hsc.vectorstore_creation`**: Creating FAISS vectorstore + hybrid retriever
- **`{filename}.hsc.parallel_field_processing`**: Processing all fields in parallel (max 5 workers)
- **Per-field timing** (inside parallel processing):
- **`{filename}.hsc.field.{field_name}.retrieval`**: BM25 + semantic retrieval + reranking
- **`{filename}.hsc.field.{field_name}.llm_call`**: Claude API call for field extraction
## How to Analyze Results
### Step 1: Run Your Pipeline
```bash
poetry run python -m src.investment.main run_mode=local read_mode=local input_dir=test-multi write_to_s3=False state=MS-IL-NY-CA-TX-WI-AR-KY-TN-ME-OH-OR-FL-AZ-IN-NJ-MI max_workers=50 client=Centene-Parkland-Molina-Moda-Healthnet-Trillium
```
### Step 2: Review Timing Summary
At the end of execution, you'll see:
1. **Total pipeline duration**
2. **Hierarchical timing summary** organized by component
Look for the output sections:
```
================================================================================
PIPELINE COMPLETE - Total time: XXX.XXs
================================================================================
HIERARCHICAL TIMING SUMMARY
================================================================================
```
### Step 3: Identify Bottlenecks
#### Key Metrics to Check:
1. **`parallel_file_processing` total time**
- This should be the largest component
- Compare to total pipeline time to see overhead
- **If this is much shorter than pipeline time**: Look for overhead in setup, I/O, or postprocessing
2. **Per-file timings** (look at individual file contexts)
- **Find the slowest files**: Look for files with longest total time
- **Identify slow components within files**: Check which stage takes longest
- Is it `one_to_one.hybrid_smart_chunking`?
- Is it `one_to_n_extraction`?
- Is it `postprocess`?
3. **Hybrid Smart Chunking (HSC) breakdown**
- **`hsc.vectorstore_creation`**: Should be relatively quick (<5s per file)
- **`hsc.parallel_field_processing`**: Often the bottleneck
- Check if fields are processing in parallel (should see ~5 fields at a time)
- Look at per-field retrieval vs llm_call times
- **`hsc.field.{field_name}.llm_call`**: LLM latency (network + Claude processing)
- High variance? Could be prompt cache issues or rate limiting
- Consistently slow? Could be context size or model load
4. **One-to-N parallel processing**
- Check if exhibits and pages are processing in parallel
- Look for imbalanced workload (some exhibits much slower than others)
### Step 4: Optimization Opportunities
#### Scenario 1: HSC Vectorstore Creation is Slow
- **Problem**: Document preprocessing/chunking is slow
- **Solution**:
- Consider caching vectorstores per document
- Reduce chunk_size or chunk_overlap in HSC_CONFIG
- Optimize preprocessing pipeline
#### Scenario 2: HSC LLM Calls are Slow
- **Problem**: Too many sequential LLM calls or high latency
- **Current**: max_workers=5 for field processing
- **Solution**:
- Increase `max_workers` in `hybrid_smart_chunking_funcs.py:304` (currently 5)
- Check Bedrock connection pool (now set to 60, should be sufficient)
- Verify prompt caching is working (check cache hits in logs)
#### Scenario 3: HSC Retrieval/Reranking is Slow
- **Problem**: RAG retrieval taking too long per field
- **Solution**:
- Reduce `ENSEMBLE_TOP_K` or `RERANKER_TOP_K` in RAG config
- Consider using faster reranker model
- Optimize BM25 index size
#### Scenario 4: Parallel File Processing Not Saturated
- **Problem**: Not all `max_workers` are being used
- **Check**:
- Connection pool exhaustion (should be fixed with `max_pool_connections=60`)
- Memory constraints (monitor memory usage)
- I/O bottlenecks (local disk or S3 bandwidth)
- **Solution**:
- Increase `max_workers` carefully (currently 50)
- Profile memory usage to find leaks
#### Scenario 5: One-to-N Exhibits Not Parallel
- **Current**: max_workers=5 for exhibit processing, max_workers=5 for page processing
- **Solution**:
- Increase these limits in `file_processing.py:244` (exhibits) and `:192` (pages)
- Balance against total file-level parallelism to avoid oversubscription
#### Scenario 6: Postprocessing is Slow
- **Problem**: Code processing or postprocessing taking too long
- **Solution**:
- Profile specific postprocessing functions
- Look for opportunities to batch operations
- Consider caching expensive lookups
## Current Parallelization Strategy
### Three Levels of Parallelism:
1. **File Level** (main.py)
- `max_workers=50` (from command line arg)
- 50 files processed simultaneously
2. **Exhibit/Page Level** (within each file)
- Exhibits: `max_workers=5` per file
- Pages: `max_workers=5` per exhibit
- This means potentially 50 files × 5 exhibits × 5 pages = 1,250 threads (too many!)
- **Currently limited by nested executors**
3. **Field Level** (within HSC per file)
- `max_workers=5` for field extraction
- 5 fields extracted in parallel per file
### Total Theoretical Concurrency:
- **Bedrock API calls**: Up to 60 concurrent (connection pool limit)
- **Thread pools**: Nested executors create complex concurrency
- **Bottleneck**: Likely the 60-connection Bedrock pool with 50 file workers
## Recommendations After First Run
1. **Run with timing enabled** and review the hierarchical summary
2. **Identify the top 3 slowest components** by total time
3. **Check if parallelism is effective**:
- Are all max_workers being utilized?
- Is there thread contention or blocking?
4. **Look for outliers**: Files that take much longer than others
5. **Profile memory usage**: Ensure no memory leaks with many threads
6. **Monitor Bedrock throttling**: Check for rate limit errors in logs
## Next Steps
Based on timing results, we can:
1. **Increase parallelism** where bottlenecks are found
2. **Add caching** for repeated operations (vectorstores, embeddings)
3. **Optimize prompts** to reduce token count and latency
4. **Batch operations** where sequential processing is required
5. **Add more granular timing** to specific slow functions
## Timing Log Format
Timing logs appear as:
```
INFO - ⏱️ read_constants: 0.50s
INFO - ⏱️ parallel_file_processing: 450.23s
DEBUG - ⏱️ file1.pdf.preprocess: 2.34s
DEBUG - ⏱️ file1.pdf.one_to_one.hybrid_smart_chunking: 45.67s
DEBUG - ⏱️ file1.pdf.hsc.setup: 0.12s
DEBUG - ⏱️ file1.pdf.hsc.vectorstore_creation: 3.45s
DEBUG - ⏱️ file1.pdf.hsc.parallel_field_processing: 40.12s
DEBUG - ⏱️ file1.pdf.hsc.field.EFFECTIVE_DT.retrieval: 0.89s
DEBUG - ⏱️ file1.pdf.hsc.field.EFFECTIVE_DT.llm_call: 2.34s
```
Use these to drill down into specific bottlenecks!