# 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!