Skip to content

Profiling & Performance Analysis

Overview

Profiling reveals where time is actually spent: - cProfile: Function-level profiling (which functions are slow?) - line_profiler: Line-by-line profiling (which lines are slow?) - Flame graphs: Visualize call stacks - CPU vs I/O: Identify the real bottleneck - JIT profiling: See where JIT helps most

Function-Level Profiling with cProfile

Basic cProfile Usage

import cProfile
import pstats

def fibonacci(n):
    """Slow recursive function."""
    if n <= 1:
        return n
    return fibonacci(n-1) + fibonacci(n-2)

# Profile the function
profiler = cProfile.Profile()
profiler.enable()

result = fibonacci(30)

profiler.disable()

# Print results
stats = pstats.Stats(profiler)
stats.sort_stats('cumulative')
stats.print_stats(10)  # Top 10 functions

# Output example:
#   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
#  2178309    0.800    0.000    2.100    0.000 example.py:1(fibonacci)
#        1    0.000    0.000    2.100    2.100 example.py:1(<module>)

Running cProfile from Command Line

python -m cProfile -s cumulative script.py | head -20
# -s: Sort by (cumulative, time, calls, etc.)
# Output shows which functions take most time

Profile Inference Loop

import cProfile
import pstats
import torch
import time

def inference_loop():
    """Profile ML inference."""
    model = torch.nn.Linear(1000, 100)
    model.eval()

    for _ in range(1000):
        x = torch.randn(32, 1000)
        with torch.no_grad():
            y = model(x)
        # Simulate some post-processing
        result = y.sum().item()

    return result

# Profile it
profiler = cProfile.Profile()
profiler.enable()

inference_loop()

profiler.disable()

# Analyze
stats = pstats.Stats(profiler)
stats.sort_stats('cumulative')
stats.print_stats(15)

# This shows if time is in:
# - PyTorch forward pass
# - Post-processing
# - Memory allocation/deallocation

Line-by-Line Profiling

Using line_profiler

# Install: pip install line_profiler

from line_profiler import LineProfiler
import numpy as np

def process_data():
    """Profile line by line."""
    data = np.random.randn(1000, 1000)  # Line 1
    mean = data.mean()                   # Line 2

    result = []
    for row in data:                     # Line 4 (loop)
        row_sum = row.sum()              # Line 5
        normalized = row / row_sum       # Line 6
        result.append(normalized)        # Line 7

    return np.array(result)              # Line 9

# Profile it
lp = LineProfiler()
lp.add_function(process_data)
lp.enable()

process_data()

lp.disable()
lp.print_stats()

# Output:
#  Line    Hits         Time  Per Hit   % Time  Line Contents
#  4      1000    1000000.0  1000.0     50.0    for row in data:
#  5      1000     500000.0   500.0     25.0        row_sum = row.sum()
#  6      1000     400000.0   400.0     20.0        normalized = row / row_sum
#  7      1000     100000.0   100.0      5.0        result.append(normalized)

Using @profile Decorator

# Decorate with @profile
@profile
def slow_function():
    total = 0
    for i in range(1000000):
        total += i ** 0.5
    return total

# Run with: python -m line_profiler script.py
# Shows time spent on each line

Identifying Bottlenecks

CPU vs I/O Bound

import cProfile
import pstats
import time
import requests

def cpu_bound():
    """CPU-bound task."""
    total = 0
    for i in range(10000000):
        total += i ** 0.5
    return total

def io_bound():
    """I/O-bound task."""
    total = 0
    for i in range(10):
        response = requests.get('https://example.com')  # Network I/O
        total += len(response.content)
    return total

# Profile CPU-bound
print("CPU-bound profiling:")
profiler = cProfile.Profile()
profiler.enable()
cpu_bound()
profiler.disable()
stats = pstats.Stats(profiler)
stats.print_stats(5)

# Bottleneck: The function itself takes time (CPU-bound)
# Solution: Use NumPy, Numba JIT, or multiprocessing

# Profile I/O-bound  
print("\nI/O-bound profiling:")
profiler = cProfile.Profile()
profiler.enable()
io_bound()
profiler.disable()
stats = pstats.Stats(profiler)
stats.print_stats(5)

# Bottleneck: Time spent in requests.get() (I/O)
# Solution: Use ThreadPoolExecutor or asyncio

Memory Profiling Combined with Speed

from line_profiler import LineProfiler
import tracemalloc
import numpy as np

def memory_and_speed():
    """Track both memory and speed."""
    tracemalloc.start()

    data = np.random.randn(10000, 10000)  # 800MB
    current, peak = tracemalloc.get_traced_memory()
    print(f"After allocation: Peak {peak / 1e6:.1f}MB")

    result = data.sum(axis=0)  # In-place sum
    current, peak = tracemalloc.get_traced_memory()
    print(f"After sum: Peak {peak / 1e6:.1f}MB")

    tracemalloc.stop()
    return result

# Profile it
import time
start = time.time()
memory_and_speed()
print(f"Total time: {time.time() - start:.2f}s")

# Result: Understand memory/speed trade-offs

Flame Graphs

Generate with py-spy

# Install: pip install py-spy

# Profile running script
py-spy record -o profile.svg -- python script.py

# Generates SVG showing call stack over time
# Wider sections = more time spent
# Useful for identifying hotspots

Example: Analyzing Flame Graph

# script.py - Long running process
import time

def slow_function():
    total = 0
    for i in range(10000000):
        total += i ** 0.5
    return total

def main():
    for _ in range(5):
        result = slow_function()
        print(result)

if __name__ == '__main__':
    main()

# Run: py-spy record -o profile.svg -- python script.py
# Result: Flame graph shows slow_function taking 90% of time

Real-World: Profiling PyTorch Inference

import torch
import cProfile
import pstats

def benchmark_inference():
    """Profile PyTorch inference."""
    model = torch.nn.Sequential(
        torch.nn.Linear(1024, 512),
        torch.nn.ReLU(),
        torch.nn.Linear(512, 256),
        torch.nn.ReLU(),
        torch.nn.Linear(256, 10)
    ).eval()

    total_time = 0
    for batch_idx in range(100):
        x = torch.randn(32, 1024)

        # Time each component
        with torch.no_grad():
            y = model(x)

        result = y.sum().item()

    return result

# Profile
profiler = cProfile.Profile()
profiler.enable()
benchmark_inference()
profiler.disable()

stats = pstats.Stats(profiler)
stats.sort_stats('cumulative')
stats.print_stats(10)

# Analysis:
# - If forward() takes 90%+: Model inference is bottleneck
# - If data loading takes 90%+: I/O is bottleneck
# - Use results to optimize (batch size, model size, etc.)

Profiling with Hooks

import time

class ProfilingHook:
    """Track function execution time."""

    def __init__(self):
        self.times = {}

    def __call__(self, name):
        def decorator(func):
            def wrapper(*args, **kwargs):
                start = time.perf_counter()
                result = func(*args, **kwargs)
                elapsed = time.perf_counter() - start

                if name not in self.times:
                    self.times[name] = []
                self.times[name].append(elapsed)

                return result
            return wrapper
        return decorator

    def print_stats(self):
        """Print profiling results."""
        for name, times in sorted(self.times.items()):
            avg_time = sum(times) / len(times)
            total_time = sum(times)
            print(f"{name}: avg {avg_time*1000:.2f}ms, total {total_time:.2f}s")

# Use it
profiler = ProfilingHook()

@profiler("forward")
def forward(x):
    time.sleep(0.01)
    return x * 2

@profiler("backward")
def backward(x):
    time.sleep(0.005)
    return x / 2

for _ in range(10):
    y = forward(5)
    z = backward(y)

profiler.print_stats()
# Output:
# backward: avg 5.03ms, total 0.05s
# forward: avg 10.02ms, total 0.10s

Summary: When to Use Each Tool

Tool Purpose When to Use
cProfile Function-level Identify slow functions
line_profiler Line-by-line Find specific slow lines
py-spy Call stacks See hot paths over time
tracemalloc Memory Find allocations
Custom hooks Application-specific Track custom metrics