# mypy: allow-untyped-defs import bisect import itertools import math from collections import defaultdict, namedtuple from operator import attrgetter from typing import Any, Optional from typing_extensions import deprecated import torch from torch.autograd import DeviceType __all__ = [ "EventList", "FormattedTimesMixin", "Interval", "Kernel", "FunctionEvent", "FunctionEventAvg", "StringTable", "MemRecordsAcc", ] class EventList(list): """A list of profiling events with helper methods for analysis and visualization. EventList extends the standard Python list to provide specialized methods for working with profiling events (FunctionEvent or FunctionEventAvg objects). It includes utilities for aggregating statistics, formatting output tables, and exporting profiling data. This class is typically returned by profiler methods and should not be instantiated directly by users. Args: *args: Standard list arguments. use_device (str, optional): Device type for profiling ("cuda", "xpu", etc.). profile_memory (bool, optional): Whether memory profiling was enabled. Default: False. with_flops (bool, optional): Whether to include FLOP counts. Default: False. Attributes: _use_device (str): Device type being profiled. _profile_memory (bool): Whether memory profiling is enabled. _with_flops (bool): Whether FLOP counting is enabled. _tree_built (bool): Whether the event tree structure has been built. Key Methods: table(...): Format events as a table string for display. export_chrome_trace(path): Export to Chrome tracing format. export_stacks(path, metric): Export stack traces with metrics. key_averages(...): Compute averaged statistics grouped by operation name. total_average(): Compute aggregate totals across all events (sums, not averages). Properties: self_cpu_time_total: Sum of self CPU time across all events. Example:: import torch from torch.profiler import profile, ProfilerActivity with profile(activities=[ProfilerActivity.CPU]) as prof: x = torch.randn(100, 100) y = torch.matmul(x, x) # EventList is returned by prof.events() events = prof.events() # Display as formatted table print( events.table( sort_by="cpu_time_total", row_limit=20, top_level_events_only=False ) ) # Export to Chrome tracing format events.export_chrome_trace("trace.json") # Get averaged statistics avg_events = events.key_averages() print(avg_events.table()) # Export stack traces events.export_stacks("stacks.txt", "self_cpu_time_total") See Also: - :class:`FunctionEvent`: Individual profiling event - :class:`FunctionEventAvg`: Averaged profiling statistics - :meth:`table`: Format events as a readable table - :meth:`key_averages`: Aggregate events by operation name """ def __init__(self, *args, **kwargs): use_device = kwargs.pop("use_device", None) profile_memory = kwargs.pop("profile_memory", False) with_flops = kwargs.pop("with_flops", False) # pyrefly: ignore [not-iterable] super().__init__(*args, **kwargs) self._use_device = use_device self._profile_memory = profile_memory self._tree_built = False self._with_flops = with_flops def _build_tree(self): self._populate_cpu_children() self._remove_dup_nodes() self._set_backward_stacktraces() self._tree_built = True def __str__(self): return self.table() def _remove_dup_nodes(self): while True: to_delete = set() for idx in range(len(self)): if ( self[idx].cpu_parent is not None and self[idx].cpu_parent.name == self[idx].name and len(self[idx].cpu_parent.cpu_children) == 1 ): self[idx].cpu_parent.cpu_children = self[idx].cpu_children self[idx].cpu_parent.kernels = self[idx].kernels # lift kernels up for ch in self[idx].cpu_children: ch.cpu_parent = self[idx].cpu_parent to_delete.add(idx) if len(to_delete) == 0: break new_evts = [ev for ind, ev in enumerate(self) if ind not in to_delete] self.clear() self.extend(new_evts) def _populate_cpu_children(self): """Populate child events into each underlying FunctionEvent object. One event is a child of another if [s1, e1) is inside [s2, e2). Where s1 and e1 would be start and end of the child event's interval. And s2 and e2 start and end of the parent event's interval Example: In event list [[0, 10], [1, 3], [3, 4]] would have make [0, 10] be a parent of two other intervals. If for any reason two intervals intersect only partially, this function will not record a parent child relationship between then. """ # Some events can be async (i.e. start and end on different threads), # since it's generally undefined how to attribute children ranges to # async ranges, we do not use them when calculating nested ranges and stats sync_events = [ evt for evt in self if not evt.is_async and evt.device_type == DeviceType.CPU ] events = sorted( sync_events, key=attrgetter("thread"), ) # Group by both thread and node_id, so that events that happen to have # the same thread_id but are from different nodes aren't incorrectly # grouped together. threads = itertools.groupby( events, key=lambda event: (event.thread, event.node_id) ) # For each thread we keep a stack of current nested parents. # We maintain the invariant that each interval is a subset of all other # intervals lower in the stack. # # First we sort the intervals by their start time. Then we iterate over them. # Every time we see a new interval we remove several parents from # the top until we restore the invariant. Then parent child relationship # if recorded if the stack is not empty. # Finally we add new interval to the list # # Algorithm has O(N * log(N)) complexity where N is number of # intervals for _thread_id, thread_events in threads: thread_events_ = sorted( thread_events, key=lambda event: [event.time_range.start, -event.time_range.end], ) current_events: list[FunctionEvent] = [] for event in thread_events_: while len(current_events) > 0: parent = current_events[-1] if ( event.time_range.start >= parent.time_range.end or event.time_range.end > parent.time_range.end ): # this can't be a parent current_events.pop() else: parent.append_cpu_child(event) if event.cpu_parent is not None: raise AssertionError( f"There is already a CPU parent event for {event.key}" ) event.set_cpu_parent(parent) break current_events.append(event) def _set_backward_stacktraces(self): def bw_parent(evt): if evt is None: return None elif evt.scope == 1: # BACKWARD_FUNCTION return evt else: return bw_parent(evt.cpu_parent) fwd_stacks = {} for evt in self: if bw_parent(evt) is None and evt.stack is not None: t = (evt.sequence_nr, evt.thread) if t not in fwd_stacks: fwd_stacks[t] = evt.stack for evt in self: p = bw_parent(evt) if p is not None: if p.fwd_thread is None: raise AssertionError( "Expected fwd_thread to be set for backward parent" ) t = (p.sequence_nr, p.fwd_thread) evt.stack = fwd_stacks.get(t, []) @property def self_cpu_time_total(self): return sum(event.self_cpu_time_total for event in self) def table( self, sort_by=None, row_limit=100, max_src_column_width=75, max_name_column_width=55, max_shapes_column_width=80, header=None, top_level_events_only=False, time_unit=None, ): """Print an EventList as a nicely formatted table. Args: sort_by (str, optional): Attribute used to sort entries. By default they are printed in the same order as they were registered. Valid keys include: ``cpu_time``, ``cuda_time``, ``xpu_time``, ``cpu_time_total``, ``cuda_time_total``, ``xpu_time_total``, ``cpu_memory_usage``, ``cuda_memory_usage``, ``xpu_memory_usage``, ``self_cpu_memory_usage``, ``self_cuda_memory_usage``, ``self_xpu_memory_usage``, ``count``. top_level_events_only(bool, optional): Boolean flag to determine the selection of events to display. If true, the profiler will only display events at top level like top-level invocation of python `lstm`, python `add` or other functions, nested events like low-level cpu/cuda/xpu ops events are omitted for profiler result readability. time_unit(str, optional): A time unit to be used for all values in the table. Valid options are: ``s``, ``ms`` and ``us``. Returns: A string containing the table. """ return _build_table( self, sort_by=sort_by, row_limit=row_limit, max_src_column_width=max_src_column_width, max_name_column_width=max_name_column_width, max_shapes_column_width=max_shapes_column_width, header=header, profile_memory=self._profile_memory, with_flops=self._with_flops, top_level_events_only=top_level_events_only, time_unit=time_unit, ) def export_chrome_trace(self, path): """Export an EventList as a Chrome tracing tools file. The checkpoint can be later loaded and inspected under ``chrome://tracing`` URL. Args: path (str): Path where the trace will be written. """ import os device_name = "cuda" if not self._use_device else self._use_device with open(path, "w") as f: next_id = 0 # Use file IO over using json.dump since JSON dumping is very slow and # this technique is proven to give a 4x speedup. f.write("[") for evt in self: if evt.trace_name is None: continue f.write( '{{"name": "{}", ' '"ph": "X", ' '"ts": {}, ' '"dur": {}, ' '"tid": {}, ' '"pid": "CPU functions", ' '"args": {{}}}}, '.format( evt.trace_name, evt.time_range.start, evt.time_range.elapsed_us(), evt.thread if not evt.is_remote else f'" node_id:{evt.node_id}, thread_id:{evt.thread} "', ) ) for _ in evt.kernels: # 's' and 'f' draw Flow arrows from # the CPU launch to the GPU kernel f.write( f'{{"name": "{evt.trace_name}", ' '"ph": "s", ' f'"ts": {evt.time_range.start}, ' f'"tid": {evt.thread}, ' '"pid": "CPU functions", ' f'"id": {next_id}, ' f'"cat": "cpu_to_{device_name}", ' '"args": {}}, ' ) # Note: use torch.profiler to get device kernel trace next_id += 1 if len(self) > 0: # remove trailing whitespace and comma f.seek(f.tell() - 2, os.SEEK_SET) f.truncate() f.write("]") def supported_export_stacks_metrics(self): return [ "self_cpu_time_total", "self_cuda_time_total", "self_xpu_time_total", "self_privateuse1_time_total", ] def export_stacks(self, path: str, metric: str): if metric not in self.supported_export_stacks_metrics(): raise ValueError( "metric should be one of: " + str(self.supported_export_stacks_metrics()) ) translate_table = str.maketrans(" ;\t\n", "____") with open(path, "w") as f: for evt in self: if evt.stack and len(evt.stack) > 0: metric_value = getattr( evt, metric.replace("cuda", "device") .replace("xpu", "device") .replace("privateuse1", "device"), ) if int(metric_value) > 0: stack_str = "" for entry in reversed(evt.stack): stack_str += entry.translate(translate_table) stack_str += ";" stack_str = stack_str[:-1] + " " + str(int(metric_value)) f.write(stack_str + "\n") def key_averages( self, group_by_input_shapes=False, group_by_stack_n=0, group_by_overload_name=False, ): """Averages all function events over their keys. Args: group_by_input_shapes: group entries by (event name, input shapes) rather than just event name. This is useful to see which input shapes contribute to the runtime the most and may help with size-specific optimizations or choosing the best candidates for quantization (aka fitting a roof line) group_by_stack_n: group by top n stack trace entries group_by_overload_name: Differentiate operators by their overload name e.g. aten::add.Tensor and aten::add.out will be aggregated separately Returns: An EventList containing FunctionEventAvg objects. """ if not self._tree_built: raise AssertionError( "Expected tree to be built before calling key_averages" ) stats: dict[tuple[str, ...], FunctionEventAvg] = defaultdict(FunctionEventAvg) def get_key( event, group_by_input_shapes, group_by_stack_n, group_by_overload_name ) -> tuple[str, ...]: key = [ str(event.key), str(event.node_id), str(event.device_type), str(event.is_legacy), str(event.is_user_annotation), ] if group_by_overload_name: key.append(evt.overload_name) if group_by_input_shapes: key.append(str(event.input_shapes)) if group_by_stack_n > 0: key += event.stack[:group_by_stack_n] return tuple(key) for evt in self: stats[ get_key( evt, group_by_input_shapes, group_by_stack_n, group_by_overload_name ) ].add(evt) avg_list = EventList( stats.values(), use_device=self._use_device, profile_memory=self._profile_memory, with_flops=self._with_flops, ) for evt in avg_list: evt.stack = evt.stack[:group_by_stack_n] if not group_by_input_shapes: evt.input_shapes = "" if not group_by_overload_name: evt.overload_name = "" return avg_list def total_average(self): """Compute aggregate statistics across all events. Accumulates statistics from all events into a single FunctionEventAvg object. This is primarily useful for computing total metrics (total CPU time, total memory usage, etc.) across the entire profiling session, regardless of operation type. Note: This sums up times and counts across ALL different operations, so the "average" metrics (like cpu_time) represent the average time per operation call across the entire session, mixing all operation types together. For per-operation averages, use :meth:`key_averages` instead. Returns: FunctionEventAvg: A single aggregate object with key="Total" containing accumulated statistics. """ total_stat = FunctionEventAvg() for evt in self: total_stat += evt total_stat.key = None total_stat.key = "Total" return total_stat def _format_time(time_us): """Define how to format time in FunctionEvent.""" US_IN_SECOND = 1000.0 * 1000.0 US_IN_MS = 1000.0 if time_us >= US_IN_SECOND: return f"{time_us / US_IN_SECOND:.3f}s" if time_us >= US_IN_MS: return f"{time_us / US_IN_MS:.3f}ms" return f"{time_us:.3f}us" def _format_time_share(time_us, total_time_us): """Define how to format time in FunctionEvent.""" if total_time_us == 0: if time_us != 0: raise AssertionError(f"Expected time_us == 0 but got {time_us}") return "NaN" return f"{time_us * 100.0 / total_time_us:.2f}%" def _format_memory(nbytes): """Return a formatted memory size string.""" KB = 1024 MB = 1024 * KB GB = 1024 * MB if abs(nbytes) >= GB: return f"{nbytes * 1.0 / GB:.2f} GB" elif abs(nbytes) >= MB: return f"{nbytes * 1.0 / MB:.2f} MB" elif abs(nbytes) >= KB: return f"{nbytes * 1.0 / KB:.2f} KB" else: return str(nbytes) + " B" def _attr_formatter(name): return property(lambda self: _format_time(getattr(self, name))) class FormattedTimesMixin: """Helpers for FunctionEvent and FunctionEventAvg. The subclass should define `*_time_total` and `count` attributes. """ cpu_time_str = _attr_formatter("cpu_time") device_time_str = _attr_formatter("device_time") cpu_time_total_str = _attr_formatter("cpu_time_total") device_time_total_str = _attr_formatter("device_time_total") self_cpu_time_total_str = _attr_formatter("self_cpu_time_total") self_device_time_total_str = _attr_formatter("self_device_time_total") @property def cpu_time(self): return 0.0 if self.count == 0 else 1.0 * self.cpu_time_total / self.count # type: ignore[attr-defined] @property def device_time(self): return 0.0 if self.count == 0 else 1.0 * self.device_time_total / self.count # type: ignore[attr-defined] @property @deprecated( "`cuda_time` is deprecated, please use `device_time` instead.", category=FutureWarning, ) def cuda_time(self): # To be deprecated return self.device_time class Interval: def __init__(self, start, end): self.start = start self.end = end def elapsed_us(self): r""" Returns the length of the interval """ return self.end - self.start Kernel = namedtuple("Kernel", ["name", "device", "duration"]) class FunctionEvent(FormattedTimesMixin): """Profiling information about a single function. FunctionEvent records the execution of a single operation during profiling. These events are obtained from the profiler/kineto and contain detailed timing and memory usage information. .. note:: FunctionEvent objects are typically created by the profiler/kineto and should not be instantiated directly by users. Access them through the profiler's output. Attributes: id (int): Unique identifier for this event. node_id (int): Node identifier for distributed profiling (-1 if not applicable). name (str): Name of the profiled function/operator. overload_name (str): Overload name for the operator (requires _ExperimentalConfig(capture_overload_names=True) set). trace_name (str): Same as name, just changes ProfilerStep* to ProfilerStep# time_range (Interval): Time interval containing start and end timestamps in microseconds. thread (int): Thread ID where the operation started. fwd_thread (int): Thread ID of the corresponding forward operation. kernels (List[Kernel]): List of device kernels launched by this operation. count (int): Number of times this event was called (usually 1). cpu_children (List[FunctionEvent]): Direct CPU child operations. cpu_parent (FunctionEvent): Direct CPU parent operation. input_shapes (Tuple[int, ...]): Shapes of input tensors (requires record_shapes=true). concrete_inputs (List[Any]): Concrete input values (requires record_shapes=true). kwinputs (Dict[str, Any]): Keyword arguments (requires record_shapes=true). stack (List[str]): Python stack trace where the operation was called (requires with_stack=true). scope (int): at::RecordScope identifier (0=forward, 1=backward, etc.). use_device (str): Device type being profiled ("cuda", "xpu", etc.). cpu_memory_usage (int): CPU memory allocated in bytes. device_memory_usage (int): Device memory allocated in bytes. is_async (bool): Whether this is an asynchronous operation. is_remote (bool): Whether this operation occurred on a remote node. sequence_nr (int): Sequence number for autograd operations. device_type (DeviceType): Type of device (CPU, CUDA, XPU, PrivateUse1, etc.). device_index (int): Index of the device (e.g., GPU 0, 1, 2). device_resource_id (int): Resource ID on the device (ie. stream ID). is_legacy (bool): Whether this is from the legacy profiler. flops (int): Estimated floating point operations. is_user_annotation (bool): Whether this is a user-annotated region. metadata_json (str): Additional metadata in JSON format. Properties: cpu_time_total (float): Total CPU time in microseconds. device_time_total (float): Total device (CUDA/XPU/etc) time in microseconds. self_cpu_time_total (float): CPU time excluding child operations. self_device_time_total (float): Device time excluding child operations. self_cpu_memory_usage (int): CPU memory usage excluding child operations. self_device_memory_usage (int): Device memory usage excluding child operations. cpu_time (float): Average CPU time per call. device_time (float): Average device time per call. key (str): Key used for grouping events (usually same as name). See Also: - :class:`torch.profiler.profile`: Context manager for profiling - :class:`EventList`: List container for FunctionEvent objects with helper methods - :class:`FunctionEventAvg`: Averaged statistics over multiple FunctionEvent objects """ def __init__( self, id, name, thread, start_us, end_us, overload_name=None, fwd_thread=None, input_shapes=None, stack=None, scope=0, use_device=None, cpu_memory_usage=0, device_memory_usage=0, is_async=False, is_remote=False, sequence_nr=-1, node_id=-1, device_type=DeviceType.CPU, device_index=0, device_resource_id=None, is_legacy=False, flops=None, trace_name=None, concrete_inputs=None, kwinputs=None, is_user_annotation=False, metadata_json=None, ): self.id: int = id self.node_id: int = node_id self.name: str = name # pyrefly: ignore [bad-assignment] self.overload_name: str = overload_name # pyrefly: ignore [bad-assignment] self.trace_name: str = trace_name self.time_range: Interval = Interval(start_us, end_us) self.thread: int = thread self.fwd_thread: Optional[int] = fwd_thread self.kernels: list[Kernel] = [] self.count: int = 1 self.cpu_children: list[FunctionEvent] = [] self.cpu_parent: Optional[FunctionEvent] = None # pyrefly: ignore [bad-assignment] self.input_shapes: tuple[int, ...] = input_shapes # pyrefly: ignore [bad-assignment] self.concrete_inputs: list[Any] = concrete_inputs # pyrefly: ignore [bad-assignment] self.kwinputs: dict[str, Any] = kwinputs # pyrefly: ignore [bad-assignment] self.stack: list = stack self.scope: int = scope self.use_device: Optional[str] = use_device self.cpu_memory_usage: int = cpu_memory_usage self.device_memory_usage: int = device_memory_usage self.is_async: bool = is_async self.is_remote: bool = is_remote self.sequence_nr: int = sequence_nr self.device_type: DeviceType = device_type self.device_index: int = device_index self.device_resource_id: int = ( thread if device_resource_id is None else device_resource_id ) self.is_legacy: bool = is_legacy self.flops: Optional[int] = flops self.is_user_annotation: Optional[bool] = is_user_annotation self.self_cpu_percent = -1 self.total_cpu_percent = -1 self.total_device_percent = -1 self.metadata_json = metadata_json def append_kernel(self, name, device, duration): if self.device_type != DeviceType.CPU: raise AssertionError("Expected device_type to be CPU") self.kernels.append(Kernel(name, device, duration)) def append_cpu_child(self, child): """Append a CPU child of type FunctionEvent. One is supposed to append only direct children to the event to have correct self cpu time being reported. """ if self.device_type != DeviceType.CPU: raise AssertionError("Expected device_type to be CPU") if not isinstance(child, FunctionEvent): raise AssertionError("Expected child to be a FunctionEvent") if child.device_type != DeviceType.CPU: raise AssertionError("Expected child device_type to be CPU") self.cpu_children.append(child) def set_cpu_parent(self, parent): """Set the immediate CPU parent of type FunctionEvent. One profiling FunctionEvent should have only one CPU parent such that the child's range interval is completely inside the parent's. We use this connection to determine the event is from top-level op or not. """ if self.device_type != DeviceType.CPU: raise AssertionError("Expected device_type to be CPU") if not isinstance(parent, FunctionEvent): raise AssertionError("Expected parent to be a FunctionEvent") if parent.device_type != DeviceType.CPU: raise AssertionError("Expected parent device_type to be CPU") self.cpu_parent = parent # Note: async events don't have children, are not used when computing 'self' # metrics of other events, have only total cpu time @property def self_cpu_memory_usage(self): if self.is_async or self.device_type != DeviceType.CPU: return 0 return self.cpu_memory_usage - sum( child.cpu_memory_usage for child in self.cpu_children ) @property def self_device_memory_usage(self): if self.is_async or self.device_type != DeviceType.CPU: return 0 return self.device_memory_usage - sum( child.device_memory_usage for child in self.cpu_children ) @property @deprecated( "`self_cuda_memory_usage` is deprecated. Use `self_device_memory_usage` instead.", category=FutureWarning, ) def self_cuda_memory_usage(self): # To be deprecated return self.self_device_memory_usage @property def cpu_time_total(self): if self.device_type == DeviceType.CPU: return self.time_range.elapsed_us() else: return 0 @property def self_cpu_time_total(self): if self.is_async or self.device_type != DeviceType.CPU: return 0 return self.cpu_time_total - sum( child.cpu_time_total for child in self.cpu_children ) @property def device_time_total(self): if self.is_async or not self.use_device: return 0 if self.device_type == DeviceType.CPU: if not self.is_legacy: # account for the kernels in the children ops return sum(kinfo.duration for kinfo in self.kernels) + sum( ch.device_time_total for ch in self.cpu_children ) else: # each legacy cpu events has a single (fake) kernel return sum(kinfo.duration for kinfo in self.kernels) else: if self.device_type not in [ DeviceType.CUDA, DeviceType.PrivateUse1, DeviceType.MTIA, DeviceType.HPU, ]: raise AssertionError( f"Expected device_type to be CUDA, PrivateUse1, MTIA, or HPU, but got {self.device_type}" ) return self.time_range.elapsed_us() @property @deprecated( "`cuda_time_total` is deprecated. Use `device_time_total` instead.", category=FutureWarning, ) def cuda_time_total(self): # To be deprecated return self.device_time_total @property def self_device_time_total(self): if self.is_async or not self.use_device: return 0 if self.device_type == DeviceType.CPU: return self.device_time_total - sum( child.device_time_total for child in self.cpu_children ) else: if self.device_type not in [ DeviceType.CUDA, DeviceType.PrivateUse1, DeviceType.MTIA, DeviceType.HPU, ]: raise AssertionError( f"Expected device_type to be CUDA, PrivateUse1, MTIA, or HPU, but got {self.device_type}" ) return self.device_time_total @property @deprecated( "`self_cuda_time_total` is deprecated. Use `self_device_time_total` instead.", category=FutureWarning, ) def self_cuda_time_total(self): # To be deprecated return self.self_device_time_total @property def key(self): return self.name def __repr__(self): device_name = self.use_device device_time = self.device_time_str device_memory_usage = self.device_memory_usage return ( f"" ) class FunctionEventAvg(FormattedTimesMixin): """Averaged profiling statistics over multiple FunctionEvent objects. FunctionEventAvg aggregates statistics from multiple FunctionEvent objects with the same key (typically same operation name). This is useful for getting average performance metrics across multiple invocations of the same operation. This class is typically created by calling :meth:`EventList.key_averages()` on a profiler's event list. Attributes: key (str): Grouping key for the events (typically operation name). count (int): Total number of events aggregated. node_id (int): Node identifier for distributed profiling (-1 if not applicable). is_async (bool): Whether the operations are asynchronous. is_remote (bool): Whether the operations occurred on a remote node. use_device (str): Device type being profiled ("cuda", "xpu", etc.). cpu_time_total (int): Accumulated total CPU time in microseconds. device_time_total (int): Accumulated total device time in microseconds. self_cpu_time_total (int): Accumulated self CPU time (excluding children) in microseconds. self_device_time_total (int): Accumulated self device time (excluding children) in microseconds. input_shapes (List[List[int]]): Input tensor shapes (requires record_shapes=true). overload_name (str): Operator overload name (requires _ExperimentalConfig(capture_overload_names=True) set). stack (List[str]): Python stack trace where the operation was called (requires with_stack=true). scope (int): at::RecordScope identifier (0=forward, 1=backward, etc.). cpu_memory_usage (int): Accumulated CPU memory usage in bytes. device_memory_usage (int): Accumulated device memory usage in bytes. self_cpu_memory_usage (int): Accumulated self CPU memory usage in bytes. self_device_memory_usage (int): Accumulated self device memory usage in bytes. cpu_children (List[FunctionEvent]): CPU child events. cpu_parent (FunctionEvent): CPU parent event. device_type (DeviceType): Type of device (CPU, CUDA, XPU, PrivateUse1, etc.). is_legacy (bool): Whether from legacy profiler. flops (int): Total floating point operations. is_user_annotation (bool): Whether this is a user-annotated region. Properties: cpu_time (float): Average CPU time per invocation. device_time (float): Average device time per invocation. See Also: - :class:`EventList.key_averages`: Method that creates FunctionEventAvg objects - :class:`FunctionEvent`: Individual profiling event - :class:`EventList`: Container for profiling events """ def __init__(self) -> None: self.key: Optional[str] = None self.count: int = 0 self.node_id: int = 0 self.is_async: bool = False self.is_remote: bool = False self.use_device: Optional[str] = None self.cpu_time_total: int = 0 self.device_time_total: int = 0 self.self_cpu_time_total: int = 0 self.self_device_time_total: int = 0 self.input_shapes: Optional[list[list[int]]] = None self.overload_name: Optional[str] = None self.stack: Optional[list] = None self.scope: Optional[int] = None self.cpu_memory_usage: int = 0 self.device_memory_usage: int = 0 self.self_cpu_memory_usage: int = 0 self.self_device_memory_usage: int = 0 self.cpu_children: Optional[list[FunctionEvent]] = None self.cpu_parent: Optional[FunctionEvent] = None self.device_type: DeviceType = DeviceType.CPU self.is_legacy: bool = False self.flops: int = 0 def add(self, other): if self.key is None: # First function being recorded as part of FunctionEventAvg, propagate # fields. self.key = other.key self.node_id = other.node_id self.is_async = other.is_async self.is_remote = other.is_remote self.cpu_parent = other.cpu_parent self.cpu_children = other.cpu_children self.overload_name = other.overload_name self.input_shapes = other.input_shapes self.stack = other.stack self.scope = other.scope self.device_type = other.device_type self.is_legacy = other.is_legacy self.use_device = other.use_device self.is_user_annotation = other.is_user_annotation if not isinstance(other, (FunctionEvent, FunctionEventAvg)): raise AssertionError( "Expected other to be a FunctionEvent or FunctionEventAvg" ) if other.key != self.key: raise AssertionError( f"Expected keys to match, but got {other.key} vs {self.key}" ) self.cpu_time_total += other.cpu_time_total self.device_time_total += other.device_time_total self.self_cpu_time_total += other.self_cpu_time_total self.self_device_time_total += other.self_device_time_total self.cpu_memory_usage += other.cpu_memory_usage self.device_memory_usage += other.device_memory_usage self.self_cpu_memory_usage += other.self_cpu_memory_usage self.self_device_memory_usage += other.self_device_memory_usage self.count += other.count if self.flops is None: # pyrefly: ignore [bad-assignment] self.flops = other.flops elif other.flops is not None: self.flops += other.flops return self def __iadd__(self, other): return self.add(other) def __repr__(self): device_name = "cuda" if not self.use_device else self.use_device self_device_time = self.self_device_time_total_str device_time = self.device_time_str device_memory = self.device_memory_usage return ( f"" ) class StringTable(defaultdict): def __missing__(self, key): # manage cases like 't' (demangled to 'unsigned short') separately, # for now simply check the length to avoid unexpected results for # the short sequences self[key] = torch._C._demangle(key) if len(key) > 1 else key return self[key] class MemRecordsAcc: """Acceleration structure for accessing mem_records in interval.""" def __init__(self, mem_records): self._mem_records = mem_records self._start_nses: list[int] = [] self._indices: list[int] = [] if len(mem_records) > 0: tmp = sorted([(r[0].start_ns(), i) for i, r in enumerate(mem_records)]) self._start_nses, self._indices = zip(*tmp) # type: ignore[assignment] def in_interval(self, start_us, end_us): r""" Return all records in the given interval To maintain backward compatibility, convert us to ns in function """ start_idx = bisect.bisect_left(self._start_nses, start_us * 1000) end_idx = bisect.bisect_right(self._start_nses, end_us * 1000) for i in range(start_idx, end_idx): yield self._mem_records[self._indices[i]] def _filter_stack_entry(entry): filtered_entries = [ ("autograd/__init__", "_make_grads"), ("autograd/__init__", "backward"), ("torch/tensor", "backward"), ("_internal/common_utils", "prof_callable"), ("_internal/common_utils", "prof_func_call"), ("_internal/common_utils", "prof_meth_call"), ] return all(not (f[0] in entry and f[1] in entry) for f in filtered_entries) MEMORY_EVENT_NAME = "[memory]" OUT_OF_MEMORY_EVENT_NAME = "[OutOfMemory]" def _filter_name(name): # ignoring the following utility ops filtered_out_names = [ MEMORY_EVENT_NAME, # used only for the top-level memory events OUT_OF_MEMORY_EVENT_NAME, "profiler::_record_function_enter", "profiler::_record_function_enter_new", "profiler::_record_function_exit", "aten::is_leaf", "aten::output_nr", "aten::_version", ] return name in filtered_out_names # Demangles and optionally rewrites the provided event name, # with_wildcard - whether to replace certain numbered event names # with a wildcard name to aggregate them together in the profiler table # output def _rewrite_name(name, with_wildcard=False): string_table = StringTable() name = string_table[name] if with_wildcard: if name.startswith("ProfilerStep#"): name = "ProfilerStep*" return name def _build_table( events, sort_by=None, header=None, row_limit=100, max_src_column_width=75, max_name_column_width=55, max_shapes_column_width=80, with_flops=False, profile_memory=False, top_level_events_only=False, time_unit=None, ): """Print a summary of events (which can be a list of FunctionEvent or FunctionEventAvg).""" if len(events) == 0: return "" has_device_time = any(event.self_device_time_total > 0 for event in events) has_device_mem = any(event.self_device_memory_usage > 0 for event in events) use_device = events[0].use_device # Running on PrivateUse1 device with profiler but not enable # ProfilerActivity.PrivateUse1 can also catch privateuse1 memory usage. # Here only need to check has_privateuse1_time if not use_device. if not use_device and has_device_time: raise RuntimeError("use_device is None, but there is device performance data.") has_input_shapes = any( (event.input_shapes is not None and len(event.input_shapes) > 0) for event in events ) has_overload_names = any( (event.overload_name is not None and len(event.overload_name) > 0) for event in events ) if sort_by is not None: events = EventList( sorted( events, key=lambda evt: getattr( evt, sort_by.replace("cuda", "device") .replace("xpu", "device") .replace("privateuse1", "device"), ), reverse=True, ), use_device=use_device, profile_memory=profile_memory, with_flops=with_flops, ) name_column_width = max(len(evt.key) for evt in events) + 4 if max_name_column_width is not None: name_column_width = min(name_column_width, max_name_column_width) shapes_column_width = max(len(str(evt.input_shapes)) for evt in events) + 4 if max_shapes_column_width is not None: shapes_column_width = min(shapes_column_width, max_shapes_column_width) DEFAULT_COLUMN_WIDTH = 12 flops_column_width = DEFAULT_COLUMN_WIDTH src_column_width = None stacks = [ evt.stack for evt in events if evt.stack is not None and len(evt.stack) > 0 ] has_stack = len(stacks) > 0 if has_stack: src_column_width = ( max(max(len(entry) for entry in stack) for stack in stacks) + 4 ) if max_src_column_width is not None: src_column_width = min(src_column_width, max_src_column_width) headers = ["Name"] if has_overload_names: headers.append("Overload Name") headers += [ "Self CPU %", "Self CPU", "CPU total %", "CPU total", "CPU time avg", ] device_name = use_device.upper() if use_device is not None else "None" if has_device_time: headers.extend( [ f"Self {device_name}", f"Self {device_name} %", f"{device_name} total", f"{device_name} time avg", ] ) if profile_memory: headers.extend( [ "CPU Mem", "Self CPU Mem", ] ) if use_device and has_device_mem: headers.extend( [ f"{device_name} Mem", f"Self {device_name} Mem", ] ) headers.append("# of Calls") # Only append Node ID if any event has a valid (>= 0) Node ID append_node_id = any(evt.node_id != -1 for evt in events) if append_node_id: headers.append("Node ID") # Have to use a list because nonlocal is Py3 only... SPACING_SIZE = 2 row_format_lst = [""] header_sep_lst = [""] line_length_lst = [-SPACING_SIZE] def add_column(padding, text_dir=">"): row_format_lst[0] += ( "{: " + text_dir + str(padding) + "}" + (" " * SPACING_SIZE) ) header_sep_lst[0] += "-" * padding + (" " * SPACING_SIZE) line_length_lst[0] += padding + SPACING_SIZE def auto_scale_flops(flops): flop_headers = [ "FLOPs", "KFLOPs", "MFLOPs", "GFLOPs", "TFLOPs", "PFLOPs", ] if flops <= 0: raise AssertionError(f"Expected flops to be positive, but got {flops}") # pyrefly: ignore [no-matching-overload] log_flops = max(0, min(math.log10(flops) / 3, float(len(flop_headers) - 1))) if not (log_flops >= 0 and log_flops < len(flop_headers)): raise AssertionError( f"Expected log_flops to be in range [0, {len(flop_headers)}), but got {log_flops}" ) return (pow(10, (math.floor(log_flops) * -3.0)), flop_headers[int(log_flops)]) add_column(name_column_width) if has_overload_names: add_column(name_column_width) for _ in headers[1 + has_overload_names :]: add_column(DEFAULT_COLUMN_WIDTH) if has_input_shapes: headers.append("Input Shapes") add_column(shapes_column_width) if has_stack: headers.append("Source Location") add_column(src_column_width, text_dir="<") if with_flops: # Auto-scaling of flops header raw_flops = [evt.flops for evt in events if evt.flops > 0] if len(raw_flops) != 0: (flops_scale, flops_header) = auto_scale_flops(min(raw_flops)) headers.append(f"Total {flops_header}") add_column(flops_column_width) else: with_flops = False # can't find any valid flops row_format = row_format_lst[0] header_sep = header_sep_lst[0] line_length = line_length_lst[0] add_column = None # type: ignore[assignment] # Have to use a list because nonlocal is Py3 only... result = [] def append(s): result.append(s) result.append("\n") # Yes, newline after the end as well sum_self_cpu_time_total = 0 sum_self_device_time_total = 0 for evt in events: sum_self_cpu_time_total += evt.self_cpu_time_total if evt.device_type == DeviceType.CPU and evt.is_legacy: # in legacy profiler, kernel info is stored in cpu events sum_self_device_time_total += evt.self_device_time_total elif ( evt.device_type in [ DeviceType.CUDA, DeviceType.PrivateUse1, DeviceType.MTIA, ] and not evt.is_user_annotation ): # in kineto profiler, there're events with the correct device type (e.g. CUDA) sum_self_device_time_total += evt.self_device_time_total # Actual printing if header is not None: append("=" * line_length) append(header) if top_level_events_only: append("=" * line_length) append("This report only display top-level ops statistics") append(header_sep) append(row_format.format(*headers)) append(header_sep) def trim_path(path, src_column_width): if len(path) > src_column_width: offset = len(path) - src_column_width path = path[offset:] if len(path) > 3: path = "..." + path[3:] return path def override_time_unit(time_us, default_str, time_unit): US_IN_SECOND = 1000.0 * 1000.0 US_IN_MS = 1000.0 if time_unit == "s": return f"{time_us / US_IN_SECOND:.3f}s" elif time_unit == "ms": return f"{time_us / US_IN_MS:.3f}ms" elif time_unit == "us": return f"{time_us:.3f}us" else: return default_str event_limit = 0 for evt in events: if event_limit == row_limit: break if top_level_events_only and evt.cpu_parent is not None: continue else: event_limit += 1 name = evt.key if max_name_column_width is not None and len(name) >= max_name_column_width - 3: name = name[: (max_name_column_width - 3)] + "..." evt.self_cpu_percent = _format_time_share( evt.self_cpu_time_total, sum_self_cpu_time_total ) evt.total_cpu_percent = ( _format_time_share(evt.cpu_time_total, sum_self_cpu_time_total) if not evt.is_async else 0 ) row_values = [name] if has_overload_names: overload_name = evt.overload_name if ( max_name_column_width is not None and len(overload_name) >= max_name_column_width - 3 ): overload_name = overload_name[: (max_name_column_width - 3)] + "..." row_values += [overload_name] row_values += [ # Self CPU total %, 0 for async events. evt.self_cpu_percent, override_time_unit( evt.self_cpu_time_total, evt.self_cpu_time_total_str, time_unit ), # Self CPU total # CPU total %, 0 for async events. evt.total_cpu_percent, override_time_unit( evt.cpu_time_total, evt.cpu_time_total_str, time_unit ), # CPU total override_time_unit( evt.cpu_time, evt.cpu_time_str, time_unit ), # CPU time avg ] if has_device_time: evt.total_device_percent = _format_time_share( evt.self_device_time_total, sum_self_device_time_total ) row_values.extend( [ override_time_unit( evt.self_device_time_total, evt.self_device_time_total_str, time_unit, ), # device time total % evt.total_device_percent, override_time_unit( evt.device_time_total, evt.device_time_total_str, time_unit ), override_time_unit( evt.device_time, evt.device_time_str, time_unit ), # device time avg ] ) if profile_memory: row_values.extend( [ # CPU Mem Total _format_memory(evt.cpu_memory_usage), # Self CPU Mem Total _format_memory(evt.self_cpu_memory_usage), ] ) if use_device and has_device_mem: row_values.extend( [ # Device Mem Total _format_memory(evt.device_memory_usage), # Self Device Mem Total _format_memory(evt.self_device_memory_usage), ] ) row_values.append( evt.count, # Number of calls ) if append_node_id: row_values.append(evt.node_id) if has_input_shapes: row_values.append(str(evt.input_shapes)[:shapes_column_width]) if with_flops: if evt.flops <= 0: row_values.append("--") else: row_values.append(f"{evt.flops * flops_scale:8.3f}") # type: ignore[possibly-undefined] if has_stack: src_field = "" if len(evt.stack) > 0: src_field = trim_path(evt.stack[0], src_column_width) row_values.append(src_field) append(row_format.format(*row_values)) if has_stack: empty_headers = [""] * (len(headers) - 1) for entry in evt.stack[1:]: append( row_format.format( *(empty_headers + [trim_path(entry, src_column_width)]) ) ) empty_headers.append("") append(row_format.format(*empty_headers)) append(header_sep) append( f"Self CPU time total: {override_time_unit(sum_self_cpu_time_total, _format_time(sum_self_cpu_time_total), time_unit)}" ) if has_device_time: append( f"Self {use_device.upper() if use_device is not None else 'None'} " f"time total: {override_time_unit(sum_self_device_time_total, _format_time(sum_self_device_time_total), time_unit)}" ) return "".join(result) # Collect all events with stack traces and format them canonically def _canonicalize_profiler_events(events): """ Extract and format all events with stack traces in a canonical way for deterministic testing. """ events_with_traces = [] for event in events: # Extract relevant fields event_name = event.get("name", "") node_name = event["args"].get("node_name", "") stack_trace = event["args"].get("stack_trace", "") # Get the last non-empty line of the stack trace lines = [s.strip() for s in stack_trace.split("\n") if s.strip()] stack_trace = lines[-1] if lines else "" events_with_traces.append( { "event_name": event_name[:20], "node_name": node_name, "stack_trace": stack_trace, "start_time": event.get("ts", 0), } ) # Sort by node_name for deterministic ordering events_with_traces.sort(key=lambda x: x["start_time"]) # Format as a string lines: list[str] = [] for evt in events_with_traces: lines.append( f"event={evt['event_name']} node={evt['node_name']} stack_trace={evt['stack_trace']}" ) return "\n".join(lines)