File size: 15,361 Bytes
7a87926 | 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334 335 336 337 338 339 340 341 342 343 344 345 346 347 348 349 350 351 352 353 354 355 356 357 358 359 360 361 362 363 364 365 366 367 368 369 370 371 372 373 374 375 376 377 378 379 380 381 382 383 384 385 386 387 388 389 390 391 392 393 394 395 396 397 398 399 400 401 402 403 404 405 406 407 408 409 410 411 412 413 414 415 416 417 418 419 420 421 422 423 424 425 426 427 428 429 430 431 432 433 434 435 436 437 438 439 440 441 442 443 444 445 446 447 448 449 450 451 452 453 454 455 456 457 458 459 460 461 462 463 464 465 466 | """
Profiling infrastructure for tracking performance metrics, hot paths, and resource utilization.
This module provides:
- Timing decorators for function-level profiling
- GPU/CPU utilization tracking
- Memory usage monitoring
- Hot path identification
- API endpoints for remote profiling access
"""
import functools
import logging
import threading
import time
from collections import defaultdict, deque
from dataclasses import asdict, dataclass, field
from typing import Any, Callable, Dict, List, Optional
try:
import torch
HAS_TORCH = True
except ImportError:
HAS_TORCH = False
try:
import psutil
HAS_PSUTIL = True
except ImportError:
HAS_PSUTIL = False
logger = logging.getLogger(__name__)
@dataclass
class ProfileEntry:
"""Single profiling entry for a function call."""
function_name: str
stage: str # e.g., "gpu", "cpu", "data_loading"
start_time: float
end_time: float
duration: float
memory_before: Optional[float] = None
memory_after: Optional[float] = None
gpu_memory_before: Optional[float] = None
gpu_memory_after: Optional[float] = None
metadata: Dict[str, Any] = field(default_factory=dict)
thread_id: int = 0
call_id: str = ""
def to_dict(self) -> Dict[str, Any]:
"""Convert to dictionary for JSON serialization."""
return asdict(self)
@dataclass
class StageStats:
"""Statistics for a pipeline stage."""
stage_name: str
call_count: int = 0
total_time: float = 0.0
min_time: float = float("inf")
max_time: float = 0.0
avg_time: float = 0.0
total_memory: float = 0.0
peak_memory: float = 0.0
gpu_total_memory: float = 0.0
gpu_peak_memory: float = 0.0
metadata: Dict[str, Any] = field(default_factory=dict)
def update(self, entry: ProfileEntry):
"""Update statistics with a new entry."""
self.call_count += 1
self.total_time += entry.duration
self.min_time = min(self.min_time, entry.duration)
self.max_time = max(self.max_time, entry.duration)
self.avg_time = self.total_time / self.call_count
if entry.memory_before is not None and entry.memory_after is not None:
memory_delta = entry.memory_after - entry.memory_before
self.total_memory += memory_delta
self.peak_memory = max(self.peak_memory, entry.memory_after)
if entry.gpu_memory_before is not None and entry.gpu_memory_after is not None:
gpu_memory_delta = entry.gpu_memory_after - entry.gpu_memory_before
self.gpu_total_memory += gpu_memory_delta
self.gpu_peak_memory = max(self.gpu_peak_memory, entry.gpu_memory_after)
def to_dict(self) -> Dict[str, Any]:
"""Convert to dictionary for JSON serialization."""
return asdict(self)
class Profiler:
"""
Global profiler for tracking performance metrics across the pipeline.
Thread-safe and designed for use in multi-threaded environments.
"""
_instance: Optional["Profiler"] = None
_lock = threading.Lock()
def __init__(self, max_entries: int = 10000, enabled: bool = True):
"""
Args:
max_entries: Maximum number of entries to keep in memory
enabled: Whether profiling is enabled
"""
self.enabled = enabled
self.max_entries = max_entries
# Thread-safe storage
self._lock = threading.Lock()
self.entries: deque = deque(maxlen=max_entries)
self.stage_stats: Dict[str, StageStats] = {}
self.function_stats: Dict[str, StageStats] = {}
# Hot path tracking (most time-consuming operations)
self.hot_paths: List[Dict[str, Any]] = []
# Current active operations (for nested profiling)
self.active_operations: Dict[int, List[str]] = defaultdict(list) # thread_id -> stack
# System metrics
self.system_metrics: List[Dict[str, Any]] = []
self._last_system_check = 0.0
self._system_check_interval = 1.0 # Check every second
@classmethod
def get_instance(cls) -> "Profiler":
"""Get singleton instance."""
if cls._instance is None:
with cls._lock:
if cls._instance is None:
cls._instance = cls()
return cls._instance
def reset(self):
"""Reset all profiling data."""
with self._lock:
self.entries.clear()
self.stage_stats.clear()
self.function_stats.clear()
self.hot_paths.clear()
self.active_operations.clear()
self.system_metrics.clear()
def _get_memory_usage(self) -> Optional[float]:
"""Get current process memory usage in MB."""
if not HAS_PSUTIL:
return None
try:
process = psutil.Process()
return process.memory_info().rss / 1024 / 1024 # MB
except Exception:
return None
def _get_gpu_memory_usage(self, device: str = "cuda:0") -> Optional[float]:
"""Get current GPU memory usage in MB."""
if not HAS_TORCH or not torch.cuda.is_available():
return None
try:
return torch.cuda.memory_allocated(device) / 1024 / 1024 # MB
except Exception:
return None
def _update_system_metrics(self):
"""Update system-level metrics (CPU, memory, GPU)."""
current_time = time.time()
if current_time - self._last_system_check < self._system_check_interval:
return
self._last_system_check = current_time
metrics = {
"timestamp": current_time,
"cpu_percent": None,
"memory_percent": None,
"gpu_memory_used": None,
"gpu_memory_total": None,
"gpu_utilization": None,
}
if HAS_PSUTIL:
try:
process = psutil.Process()
metrics["cpu_percent"] = process.cpu_percent()
metrics["memory_percent"] = process.memory_percent()
except Exception:
pass
if HAS_TORCH and torch.cuda.is_available():
try:
metrics["gpu_memory_used"] = torch.cuda.memory_allocated() / 1024 / 1024 # MB
metrics["gpu_memory_total"] = (
torch.cuda.get_device_properties(0).total_memory / 1024 / 1024
) # MB
# GPU utilization requires nvidia-ml-py, skip for now
except Exception:
pass
with self._lock:
self.system_metrics.append(metrics)
if len(self.system_metrics) > 1000: # Keep last 1000 samples
self.system_metrics.pop(0)
def start_operation(self, function_name: str, stage: str = "unknown", **metadata) -> str:
"""
Start profiling an operation.
Returns:
call_id: Unique identifier for this call
"""
if not self.enabled:
return ""
call_id = f"{function_name}_{time.time()}_{threading.get_ident()}"
thread_id = threading.get_ident()
entry = ProfileEntry(
function_name=function_name,
stage=stage,
start_time=time.time(),
end_time=0.0,
duration=0.0,
memory_before=self._get_memory_usage(),
gpu_memory_before=self._get_gpu_memory_usage(),
metadata=metadata,
thread_id=thread_id,
call_id=call_id,
)
with self._lock:
self.active_operations[thread_id].append(call_id)
# Store entry temporarily (will be updated on end)
# We'll store it in metadata for now
entry.metadata["_temp_entry"] = entry
self._update_system_metrics()
return call_id
def end_operation(self, call_id: str):
"""End profiling an operation."""
if not self.enabled or not call_id:
return
thread_id = threading.get_ident()
# Find the entry (stored in active_operations)
with self._lock:
if (
thread_id in self.active_operations
and call_id in self.active_operations[thread_id]
):
# We need to reconstruct the entry
# For now, we'll use a simpler approach: store in a dict
pass
# Simplified: create entry on end
# In practice, we'd track the start entry
# For now, we'll use a decorator-based approach instead
self._update_system_metrics()
def record(self, function_name: str, stage: str, duration: float, **metadata):
"""
Record a completed operation.
Args:
function_name: Name of the function
stage: Pipeline stage (e.g., "gpu", "cpu", "data_loading")
duration: Duration in seconds
**metadata: Additional metadata
"""
if not self.enabled:
return
thread_id = threading.get_ident()
entry = ProfileEntry(
function_name=function_name,
stage=stage,
start_time=time.time() - duration,
end_time=time.time(),
duration=duration,
memory_before=self._get_memory_usage(),
memory_after=self._get_memory_usage(),
gpu_memory_before=self._get_gpu_memory_usage(),
gpu_memory_after=self._get_gpu_memory_usage(),
metadata=metadata,
thread_id=thread_id,
call_id=f"{function_name}_{time.time()}_{thread_id}",
)
with self._lock:
self.entries.append(entry)
# Update stage statistics
if stage not in self.stage_stats:
self.stage_stats[stage] = StageStats(stage_name=stage)
self.stage_stats[stage].update(entry)
# Update function statistics
if function_name not in self.function_stats:
self.function_stats[function_name] = StageStats(stage_name=function_name)
self.function_stats[function_name].update(entry)
# Update hot paths (top N by total time)
self._update_hot_paths()
self._update_system_metrics()
def _update_hot_paths(self):
"""Update hot paths list (top operations by total time)."""
with self._lock:
# Aggregate by function name
function_totals: Dict[str, float] = defaultdict(float)
for entry in self.entries:
function_totals[entry.function_name] += entry.duration
# Sort by total time
sorted_functions = sorted(function_totals.items(), key=lambda x: x[1], reverse=True)
self.hot_paths = [
{
"function": func,
"total_time": total,
"call_count": self.function_stats.get(func, StageStats(func)).call_count,
"avg_time": self.function_stats.get(func, StageStats(func)).avg_time,
}
for func, total in sorted_functions[:20] # Top 20
]
def get_metrics(self) -> Dict[str, Any]:
"""Get all profiling metrics."""
with self._lock:
return {
"enabled": self.enabled,
"total_entries": len(self.entries),
"stage_stats": {
stage: stats.to_dict() for stage, stats in self.stage_stats.items()
},
"function_stats": {
func: stats.to_dict() for func, stats in self.function_stats.items()
},
"hot_paths": self.hot_paths,
"system_metrics": (
self.system_metrics[-100:] if self.system_metrics else []
), # Last 100 samples
}
def get_stage_stats(self, stage: str) -> Optional[Dict[str, Any]]:
"""Get statistics for a specific stage."""
with self._lock:
if stage in self.stage_stats:
return self.stage_stats[stage].to_dict()
return None
def get_latency_breakdown(self) -> Dict[str, Any]:
"""Get latency breakdown by stage."""
with self._lock:
breakdown = {}
total_time = sum(stats.total_time for stats in self.stage_stats.values())
for stage, stats in self.stage_stats.items():
percentage = (stats.total_time / total_time * 100) if total_time > 0 else 0
breakdown[stage] = {
"total_time": stats.total_time,
"avg_time": stats.avg_time,
"call_count": stats.call_count,
"percentage": percentage,
}
return {
"total_time": total_time,
"breakdown": breakdown,
}
def profile(stage: str = "unknown", **metadata):
"""
Decorator for profiling functions.
Usage:
@profile(stage="gpu")
def my_function():
...
"""
def decorator(func: Callable) -> Callable:
@functools.wraps(func)
def wrapper(*args, **kwargs):
profiler = Profiler.get_instance()
if not profiler.enabled:
return func(*args, **kwargs)
start_time = time.time()
try:
result = func(*args, **kwargs)
duration = time.time() - start_time
profiler.record(
function_name=func.__name__, stage=stage, duration=duration, **metadata
)
return result
except Exception as e:
duration = time.time() - start_time
profiler.record(
function_name=func.__name__,
stage=stage,
duration=duration,
error=str(e),
**metadata,
)
raise
return wrapper
return decorator
def profile_context(stage: str = "unknown", **metadata):
"""
Context manager for profiling code blocks.
Usage:
with profile_context(stage="gpu"):
# code to profile
"""
class ProfileContext:
def __init__(self, stage: str, **metadata):
self.stage = stage
self.metadata = metadata
self.profiler = Profiler.get_instance()
self.start_time = None
def __enter__(self):
if self.profiler.enabled:
self.start_time = time.time()
return self
def __exit__(self, exc_type, exc_val, exc_tb):
if self.profiler.enabled and self.start_time is not None:
duration = time.time() - self.start_time
# Get function name from stack
import inspect
frame = inspect.currentframe().f_back
function_name = frame.f_code.co_name if frame else "unknown"
self.profiler.record(
function_name=function_name,
stage=self.stage,
duration=duration,
**self.metadata,
)
return False
return ProfileContext(stage, **metadata)
|