analyzing-blackfire-profiles

# Blackfire Performance Investigation Systematic approach to analyzing Blackfire.io performance profiles using Chrome browser automation. ## Prerequisites - Chrome browser with Claude-in-Chrome MCP extension - Access to Blackfire.io (profile URL) --- ## CRITICAL: Sidebar Fix (MUST DO FIRST) **STOP! Before ANY callgraph analysis, you MUST apply this JavaScript fix.** The default Blackfire UI truncates function names (e.g., `...ecute(...)`) making analysis **impossible**. This fix is **NON-NEGOTIABLE**. ```javascript document.querySelector('.graph-pane').style.position = 'static'; document.querySelectorAll('div').forEach(d => { if(d.style.cssText.includes('position: fixed') && d.style.cssText.includes('height: 100%')) d.style.width = '1400px'; }); ``` **When to apply:** Immediately after navigating to any Blackfire profile, BEFORE reading the callgraph. **What it does:** Hides the visual graph and widens the sidebar to show full function names like `Doctrine\ORM\UnitOfWork::computeChangeSet` instead of `...Work::compu...`. **If you skip this:** You cannot identify functions, making all subsequent analysis meaningless. --- ## Investigation Workflow ``` ┌─────────────────────────────────────────────────────────────┐ │ STEP 0: APPLY SIDEBAR FIX (MANDATORY - DO THIS FIRST!) │ │ └─ Run JavaScript fix immediately after page load │ ├─────────────────────────────────────────────────────────────┤ │ STEP 1: HEADER TRIAGE (5 seconds) │ │ └─ Identify bottleneck TYPE: I/O vs CPU vs Memory │ ├─────────────────────────────────────────────────────────────┤ │ STEP 2: BRANCH TO SPECIALIZED VIEW │ │ ├─ I/O-bound → SQL/HTTP view first │ │ ├─ CPU-bound → Callgraph first │ │ └─ Unclear → "All" view to disambiguate │ ├─────────────────────────────────────────────────────────────┤ │ STEP 3: CALLGRAPH DEEP DIVE │ │ └─ Three-sort → Drill-down → Focused view │ ├─────────────────────────────────────────────────────────────┤ │ STEP 4: RECOMMENDATIONS + TIMELINE (if needed) │ └─────────────────────────────────────────────────────────────┘ ``` --- ### 1. Header Triage (Decision Point) **This is the most important step.** The header tells you WHERE to look next. After navigation, read the header bar metrics: ``` ┌──────────────┬──────────────┬──────────────┬──────────────┬──────────────┐ │ Wall Time │ I/O Wait │ CPU │ Memory │ Network │ │ 15.4 s │ 4.78 s │ 10.6 s │ 165 MB │ 2.9 MB │ └──────────────┴──────────────┴──────────────┴──────────────┴──────────────┘ ``` #### Branching Decision Tree **Calculate the dominant dimension:** | If Header Shows | Bottleneck Type | Next Step | |-----------------|-----------------|-----------| | **I/O Wait > 50% of Wall Time** | I/O-bound (database, network) | → Go to **SQL/HTTP View** | | **CPU > 50% of Wall Time** | CPU-bound (computation) | → Go to **Callgraph** | | **~50/50 split or unclear** | Mixed workload | → Use **"All" View** to disambiguate | | **Memory very high** | Memory-bound | → Check hydration count, then Callgraph | **Example calculations:** - Wall Time 15.4s, I/O 4.78s (31%), CPU 10.6s (69%) → **CPU-bound** → Callgraph first - Wall Time 10s, I/O 7s (70%), CPU 3s (30%) → **I/O-bound** → SQL view first - Wall Time 8s, I/O 4s (50%), CPU 4s (50%) → **Unclear** → Use "All" view #### Why This Matters > **"Optimize the dominating bottleneck first."** - Performance Engineering Principle If the profile is 70% I/O wait, drilling into CPU-heavy functions wastes time. The header tells you which tool to use: - High I/O → SQL view will show the slow queries - High CPU → Callgraph will show the heavy functions --- ### 2A. SQL/HTTP View (For I/O-Bound Profiles) **Use this when:** Header shows I/O Wait > 50% of Wall Time Click **SQL** in left sidebar for database analysis. **What to check:** - **Calls column** - Anything >50 is likely N+1 pattern - **Time column** - Slow individual queries - Sort by Calls descending (default) to see worst offenders **Red flags:** | Pattern | Threshold | |---------|-----------| | Same query repeated | >50 calls | | High entity count | >1000 | | Total queries | >100 for simple page | Click **HTTP** for external API calls: - External service calls (Elasticsearch, APIs) - Call counts and timing - **Red flag:** >10 external calls per request **After SQL/HTTP analysis:** Proceed to Callgraph (Step 3) to find the CODE causing these queries. --- ### 2B. "All" View (For Unclear/Mixed Profiles) **Use this when:** Header shows ~50/50 split between I/O and CPU, or you need per-function dimensional breakdown. Click **"All"** button in the header bar (next to "Wall Time"). **What "All" view provides:** - Per-function breakdown of ALL dimensions side-by-side - See which specific functions are I/O-heavy vs CPU-heavy - Columns: Time, I/O Wait, CPU, Memory, Network (each with % Excl / % Incl) **When to use:** - Header totals are ambiguous (~50/50) - You suspect different functions have different bottleneck types - Need to see the full picture before drilling down **After "All" view analysis:** Click the specific dimension header (Wall Time, CPU, etc.) to switch to that focused view for deeper analysis. --- ### 3. Callgraph Analysis (Primary Deep Dive) Click **Callgraph** in left sidebar. This is the most powerful view for finding root causes. #### Step 1: Apply Sidebar Full-Width Fix (MANDATORY) **Run this immediately** - default view truncates function names making analysis impossible: ```javascript document.querySelector('.graph-pane').style.position = 'static'; document.querySelectorAll('div').forEach(d => { if(d.style.cssText.includes('position: fixed') && d.style.cssText.includes('height: 100%')) d.style.width = '1400px'; }); ``` This hides the graph and widens the sidebar to show full names like `Doctrine\ORM\UnitOfWork::computeChangeSet`. #### Step 2: Understand the Columns | Column | What It Shows | Best For | |--------|---------------|----------| | **Function calls** | Full function name with namespace | Identifying what code is running | | **% Excl.** | Time spent IN this function (not children) | Finding hot spots - where time actually burns | | **% Incl.** | Time spent in function + all children | Understanding call hierarchy top-down | | **Calls** | Number of times function was called | Detecting N+1 patterns and loops | #### Step 3: Three-Sort Analysis Workflow **This is the core debugging workflow.** Use all three sorts: ##### Sort 1: % Excl. (Default) - Find Hot Spots - **Red bars = hot spots** - functions consuming most exclusive time - Look for: Application code with big red bars (your code, not framework) - Common hot spots: `PDOStatement::execute`, `ObjectHydrator::*`, event listeners ##### Sort 2: Calls (Click header) - Find N+1 and Loops Click "Calls" column to sort by call count descending. | Call Count | Likely Issue | |------------|--------------| | >100K | Framework overhead from too many entities | | >10K | Possible N+1 or excessive lazy loading | | >1K | Worth investigating if exclusive time is also high | **Pattern recognition:** - `hydrateColumnInfo` 900K+ calls → too many entities hydrated - `postLoad` listener count ≈ number of entities loaded ##### Sort 3: % Incl. (Click header) - Understand Call Hierarchy - Shows the **call chain from entry point** down - First rows: `main()` → `Kernel::handle` → `Controller::action` - Helps identify: Which controller/action is profiled, major code paths #### Step 4: Drill-Down Analysis (Function Details Panel) **Click any function row** to open the details panel. **Panel Structure:** 1. **Callers Section** (orange bar at top) - "↓ N times (X%)" = caller invoked it N times - Click to expand caller details 2. **Function Metrics** (middle) - Wall time, I/O time, CPU time, Memory, Network - **Color bars**: Orange = exclusive, Purple/Cyan = children 3. **Callees Section** (colored bars at bottom) - **Click colored bars to expand** and see callee details - Colors: Yellow (largest), Blue, Pink, Grey **Drill-Down Workflow:** ``` 1. Click hot spot in list (high % Excl.) 2. Look at callees - which child consumes most time? 3. Click that callee's bar to expand 4. Repeat until you find the root cause ``` #### Step 5: Focused View (Isolate Call Tree) **Click the magnifying glass icon (🔍)** next to any function name. **What it does:** - Filters to show ONLY functions in that call tree - Removes all unrelated framework noise - Shows all callers (upstream) and callees (downstream) **To exit:** Click "All" button in header or reload page. --- ### 4. Recommendations Click **Recommendations** (badge shows count) for automated findings. **Common issues detected:** - eval() usage (should be 0) - ORM entity count violations - HTTP call count - Debug mode in production - Garbage collection triggers Click **"How to fix"** for remediation guidance. --- ### 5. Timeline Analysis (Advanced) Click **Timeline** for chronological execution view. Use when execution order matters. **Before using Timeline:** Run `location.reload(true)` to reset the UI after sidebar fix. #### Key Metrics | Metric | Warning | Critical | |--------|---------|----------| | doctrine.entities.hydrated | >1000 | >5000 | | doctrine.orm.flush | >5 | >20 | | sql | >100 | >500 | | http.curl.requests | >10 | >50 | #### Visual Patterns | Pattern | Indicates | |---------|-----------| | Many thin vertical blocks | N+1 queries | | Sudden memory spike | Large allocation/leak | | Wide single block | Long-running function | | Gaps in timeline | I/O wait / external calls | --- ## Quick Reference ### Thresholds | Metric | Warning | Critical | |--------|---------|----------| | Wall Time | >5s | >15s | | Same SQL query | >50x | >200x | | ORM entities | >5K | >20K | | External HTTP | >10 | >50 | ### Workflow Cheat Sheet ``` 1. HEADER TRIAGE ├─ I/O > 50%? → SQL view → Find slow/repeated queries ├─ CPU > 50%? → Callgraph → Find heavy functions └─ Unclear? → "All" view → See per-function breakdown 2. CALLGRAPH (always needed for root cause) ├─ Apply sidebar fix (MANDATORY) ├─ % Excl. sort → Find hot spots ├─ Calls sort → Find N+1 patterns └─ Drill-down → Trace to root cause 3. FOCUSED VIEW └─ Click 🔍 → Isolate one call tree 4. RECOMMENDATIONS └─ Check automated findings ``` ### Reporting Findings ``` | Component | Time | % of Total | |-----------|------|------------| | Total Request | Xs | 100% | | Function A | Xs | X% | | → Child B | Xs | X% | ``` --- ## Tips - **Header triage first** - Know if I/O or CPU before deep diving - **Apply sidebar fix immediately** - Without full names, analysis is impossible - **Three-sort workflow** - % Excl. (hot spots), Calls (N+1), % Incl. (hierarchy) - **Drill-down with details panel** - Click function → expand callee bars → repeat - **Focused view for isolation** - Click 🔍 to filter to one call tree - **"All" view for mixed workloads** - When header shows ~50/50 I/O/CPU split - **Timeline for sequence** - Use when execution order matters - **Hard refresh resets everything** - `location.reload(true)` after sidebar fix