analyzing-blackfire-profiles

name

analyzing-blackfire-profiles

description

Use PROACTIVELY when you investigate, analyze, debug, or review performance issues using Blackfire.io profiles. Triggers on: 'blackfire profile', 'performance analysis', 'investigate slow', 'profile URL', app.blackfire.io URLs, slow requests, high CPU/IO, N+1 detection, or query optimization. Covers: header triage, callgraph analysis, SQL/HTTP views, timeline inspection, drill-down debugging, and interpreting recommendations.

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.

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:

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