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

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

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

-

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

Flame Graphs

Generate with py-spy

# Install

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

-

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%+
# - If data loading takes 90%+
# - 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
# forward

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

-