_utils.py 21 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569
  1. # mypy: allow-untyped-defs
  2. import functools
  3. import operator
  4. import re
  5. from collections import deque
  6. from dataclasses import dataclass
  7. from typing import Any, Literal, TYPE_CHECKING
  8. from torch.autograd.profiler import profile
  9. from torch.profiler import DeviceType
  10. if TYPE_CHECKING:
  11. from torch.autograd import _KinetoEvent
  12. def _traverse(tree, next_fn, children_fn=lambda x: x.children, reverse: bool = False):
  13. order = reversed if reverse else lambda x: x
  14. remaining = deque(order(tree))
  15. while remaining:
  16. curr_event = next_fn(remaining)
  17. yield curr_event
  18. for child_event in order(children_fn(curr_event)):
  19. remaining.append(child_event)
  20. traverse_dfs = functools.partial(_traverse, next_fn=lambda x: x.pop(), reverse=True)
  21. traverse_bfs = functools.partial(
  22. _traverse, next_fn=lambda x: x.popleft(), reverse=False
  23. )
  24. @dataclass
  25. class EventMetrics:
  26. duration_time_ns: int = 0
  27. self_time_ns: int = 0
  28. idle_time_ns: int = 0
  29. queue_depth: int = 0
  30. @property
  31. def fraction_idle_time(self):
  32. if self.duration_time_ns == 0:
  33. return 0.0
  34. return self.idle_time_ns / self.duration_time_ns
  35. @dataclass
  36. class Interval:
  37. start: int
  38. end: int
  39. queue_depth: int = 0
  40. class EventKey:
  41. def __init__(self, event) -> None:
  42. self.event = event
  43. def __hash__(self):
  44. return hash(self.event.id)
  45. def __eq__(self, other):
  46. return self.event.id == other.event.id
  47. def __repr__(self) -> str:
  48. return f"{self.event.name}"
  49. def intervals_overlap(self, intervals: list[Interval]):
  50. overlap_time = 0
  51. intervals = sorted(intervals, key=lambda x: x.start)
  52. if intervals:
  53. overlap_start = max(self.event.start_time_ns, intervals[0].start)
  54. overlap_end = min(self.event.end_time_ns, intervals[0].end)
  55. if overlap_start < overlap_end:
  56. overlap_time += overlap_end - overlap_start
  57. i, j = 0, 1
  58. while j < len(intervals):
  59. prev_interval = intervals[i]
  60. curr_interval = intervals[j]
  61. j += 1
  62. if prev_interval.end > curr_interval.start:
  63. # Completely subsumed by previous interval
  64. if prev_interval.end > curr_interval.end:
  65. j += 1
  66. continue
  67. else:
  68. curr_interval.start = prev_interval.end
  69. i = j
  70. overlap_start = max(self.event.start_time_ns, curr_interval.start)
  71. overlap_end = min(self.event.end_time_ns, curr_interval.end)
  72. if overlap_start < overlap_end:
  73. overlap_time += overlap_end - overlap_start
  74. return overlap_time
  75. class BasicEvaluation:
  76. def __init__(self, prof: profile) -> None:
  77. self.profile = prof
  78. self.metrics: dict[EventKey, EventMetrics] = {}
  79. self.compute_self_time()
  80. self.event_keys = sorted(
  81. self.metrics.keys(), key=lambda x: x.event.start_time_ns
  82. )
  83. self.events = [e.event for e in self.event_keys]
  84. self.cuda_events: list[_KinetoEvent] = []
  85. self.queue_depth_list = self.compute_queue_depth()
  86. self.compute_idle_time()
  87. def compute_self_time(self) -> None:
  88. """
  89. Computes event's self time(total time - time in child ops).
  90. """
  91. assert self.profile.kineto_results is not None
  92. stack = deque(self.profile.kineto_results.experimental_event_tree())
  93. # standard iterating dfs
  94. while stack:
  95. curr_event = stack.pop()
  96. self_time = curr_event.duration_time_ns
  97. for child_event in curr_event.children:
  98. self_time -= child_event.duration_time_ns
  99. stack.append(child_event)
  100. assert EventKey(curr_event) not in self.metrics, (
  101. f"Duplicate id: {curr_event.id}, {curr_event.name}"
  102. )
  103. self.metrics[EventKey(curr_event)] = EventMetrics(self_time_ns=self_time)
  104. self.metrics[
  105. EventKey(curr_event)
  106. ].duration_time_ns = curr_event.duration_time_ns
  107. def compute_queue_depth(self):
  108. """
  109. Computes queue_depth at each event. This will calculate the queue depth data for
  110. All the events in the tree.
  111. This will return a list of Interval of queue depth data of cuda launch and kernels.
  112. """
  113. assert self.profile.kineto_results is not None
  114. cuda_event_list = self.profile.kineto_results.events()
  115. def is_cuda_launch_kernel(e):
  116. """Check if the event is a CUDA launch kernel."""
  117. launch_patterns = {
  118. "cudaLaunchKernel", # Standard CUDA
  119. "cudaLaunchKernelExC", # Extended C
  120. "__cudaLaunchKernel", # Internal
  121. "cudaLaunchCooperativeKernel", # Collaborative (single-device)
  122. "cudaLaunchCooperativeKernelMultiDevice", # Collaborative (multi-devices)
  123. }
  124. name = str(getattr(e, "name", e))
  125. return any(name.startswith(pattern) for pattern in launch_patterns)
  126. def is_cuda_kernel(e):
  127. """Check if the event is a CUDA runtime kernel."""
  128. # Check if the kernel is CUDA
  129. if e.device_type() != DeviceType.CUDA:
  130. return False
  131. name = str(getattr(e, "name", e)).lower()
  132. # Exclude memory operations
  133. exclude_patterns = {"mem", "cpy", "alloc", "free"}
  134. return not any(pattern in name for pattern in exclude_patterns)
  135. cuda_launch_events = sorted(
  136. (e for e in cuda_event_list if is_cuda_launch_kernel(e)),
  137. key=lambda x: x.start_ns(),
  138. )
  139. cuda_kernel_events = sorted(
  140. (e for e in cuda_event_list if is_cuda_kernel(e)),
  141. key=lambda x: x.start_ns(),
  142. )
  143. self.cuda_events = sorted(
  144. cuda_launch_events + cuda_kernel_events, key=lambda x: x.start_ns()
  145. )
  146. kernel_mapping: dict[_KinetoEvent, int] = {}
  147. last_mapped_kernel = 0
  148. for cuda_launch_event in cuda_launch_events:
  149. index = index_of_first_match(
  150. cuda_kernel_events,
  151. lambda x: x.linked_correlation_id()
  152. == cuda_launch_event.linked_correlation_id(),
  153. start=last_mapped_kernel,
  154. )
  155. kernel_mapping[cuda_launch_event] = index
  156. last_mapped_kernel = index if index is not None else last_mapped_kernel
  157. current_kernel_index = 0
  158. spawned_kernel_index = -1
  159. all_events = cuda_launch_events + cuda_kernel_events + self.events
  160. def new_old_event_comparator(event):
  161. if hasattr(event, "start_us"):
  162. return event.start_us() * 1000
  163. if hasattr(event, "start_ns"):
  164. return event.start_ns()
  165. if hasattr(event, "start_time_ns"):
  166. return event.start_time_ns
  167. raise Exception("Unknown Event Type") # noqa: TRY002
  168. queue_depth_list: list[Interval] = []
  169. all_events.sort(key=new_old_event_comparator)
  170. for event in all_events:
  171. # Find latest cuda kernel event
  172. if hasattr(event, "start_us"):
  173. start_time = event.start_us() * 1000
  174. # pyrefly: ignore [missing-attribute]
  175. end_time = (event.start_us() + event.duration_us()) * 1000
  176. # Find current spawned cuda kernel event
  177. if event in kernel_mapping and kernel_mapping[event] is not None:
  178. spawned_kernel_index = kernel_mapping[event]
  179. if hasattr(event, "start_ns"):
  180. start_time = event.start_ns()
  181. end_time = event.start_ns() + event.duration_ns()
  182. # Find current spawned cuda kernel event
  183. if event in kernel_mapping and kernel_mapping[event] is not None:
  184. spawned_kernel_index = kernel_mapping[event]
  185. elif hasattr(event, "start_time_ns"):
  186. start_time = event.start_time_ns # type: ignore[attr-defined]
  187. end_time = event.end_time_ns # type: ignore[attr-defined]
  188. while (
  189. current_kernel_index < len(cuda_kernel_events)
  190. and (cuda_kernel_events[current_kernel_index].start_ns()) <= start_time # type: ignore[possibly-undefined]
  191. ):
  192. current_kernel_index += 1
  193. current_queue_depth = spawned_kernel_index - current_kernel_index + 1
  194. current_queue_depth = max(current_queue_depth, 0)
  195. if hasattr(event, "start_us") or hasattr(event, "start_ns"):
  196. queue_depth_list.append(
  197. Interval(start_time, end_time, current_queue_depth) # type: ignore[possibly-undefined]
  198. )
  199. elif hasattr(event, "start_time_ns"):
  200. self.metrics[EventKey(event)].queue_depth = current_queue_depth
  201. return queue_depth_list
  202. def compute_idle_time(self) -> None:
  203. """
  204. Computes idle time of the profile.
  205. """
  206. # Based on queue_depth_list, we can calculate idle time for all the events
  207. idle = False
  208. idle_start = 0
  209. idle_intervals: list[Interval] = []
  210. if self.queue_depth_list and self.events:
  211. idle_intervals += [
  212. Interval(self.events[0].start_time_ns, self.queue_depth_list[0].start),
  213. Interval(self.queue_depth_list[-1].end, self.events[-1].end_time_ns),
  214. ]
  215. for data_point in self.queue_depth_list:
  216. if data_point.queue_depth == 0 and not idle:
  217. idle_start = data_point.end
  218. idle = True
  219. if data_point.queue_depth > 0 and idle:
  220. idle_intervals.append(Interval(idle_start, data_point.start))
  221. idle = False
  222. event_list = [e.event for e in self.metrics]
  223. for event in event_list:
  224. self.metrics[EventKey(event)].idle_time_ns = EventKey(
  225. event
  226. ).intervals_overlap(idle_intervals)
  227. def rank_events(self, length):
  228. """
  229. Filter and Rank the events based on some heuristics:
  230. 1) Events that are in the falling phase of the queue depth.
  231. 2) Events that have a high idle_time, self_time difference.
  232. Parameters:
  233. length: The number of events to return.
  234. """
  235. # Find the interval when qd is falling to 0
  236. import torch
  237. queue_depth_list = list(reversed(self.queue_depth_list))
  238. qd_values = [e.queue_depth for e in queue_depth_list]
  239. bottom_threashold = 0
  240. top_threashold = 4
  241. decrease_interval = []
  242. i = 0
  243. while i < len(qd_values):
  244. if qd_values[i] > bottom_threashold:
  245. i += 1
  246. continue
  247. for j in range(i + 1, len(qd_values)):
  248. # Find next zero and if the max value between them exceeds
  249. # the threshold, then we have a falling interval
  250. next_minimum_idx = index_of_first_match(
  251. qd_values, lambda x: x <= bottom_threashold, start=j
  252. )
  253. peak_idx = argmax(qd_values, start=j, end=next_minimum_idx)
  254. # if is a valid peak, we add to list and continue
  255. if peak_idx is not None and qd_values[peak_idx] >= top_threashold:
  256. decrease_interval.append(
  257. Interval(
  258. queue_depth_list[peak_idx].start, queue_depth_list[i].start
  259. )
  260. )
  261. i = next_minimum_idx if next_minimum_idx is not None else i
  262. break
  263. i += 1
  264. # Filter out events that are not in the decrease interval
  265. event_list = [
  266. event
  267. for event in self.metrics
  268. if event.intervals_overlap(decrease_interval)
  269. ]
  270. if event_list:
  271. self_time = torch.tensor(
  272. [self.metrics[event].self_time_ns for event in event_list],
  273. dtype=torch.float32,
  274. )
  275. idle_time = torch.tensor(
  276. [self.metrics[event].fraction_idle_time for event in event_list],
  277. dtype=torch.float32,
  278. )
  279. normalized_gain = (idle_time - torch.mean(idle_time)) / torch.std(idle_time)
  280. normalized_self = (self_time - torch.mean(self_time)) / torch.std(self_time)
  281. heuristic_score_list = normalized_gain + 0.6 * normalized_self
  282. # Sort events by heuristic
  283. event_list = [
  284. event
  285. for _, event in sorted(
  286. zip(heuristic_score_list, event_list, strict=True),
  287. key=operator.itemgetter(0),
  288. reverse=True,
  289. )
  290. ]
  291. event_list = event_list[:length]
  292. return event_list
  293. def get_optimizable_events(self, length: int = 1, print_enable: bool = True):
  294. event_list = self.rank_events(length)
  295. if not print_enable:
  296. return event_list
  297. output = "Optimizable events:\n" if event_list else "No events to optimize\n"
  298. output += "\n".join(
  299. [
  300. f"""{"-" * 80}
  301. Event: {event}
  302. Source code location: {source_code_location(event.event)}
  303. Percentage idle time: {self.metrics[event].fraction_idle_time * 100:.2f}%
  304. {"-" * 80}"""
  305. for event in event_list
  306. ]
  307. )
  308. if print_enable:
  309. print(output)
  310. return event_list
  311. def index_of_first_match(seq, predicate, start=0, end=None):
  312. if end is None or end >= len(seq):
  313. end = len(seq)
  314. for i in range(start, end):
  315. if predicate(seq[i]):
  316. return i
  317. return None
  318. def argmax(seq, key=lambda x: x, start=0, end=None):
  319. seq = seq[start:end]
  320. if len(seq) == 0:
  321. return None
  322. return seq.index(max(seq, key=key)) + start
  323. def source_code_location(event):
  324. while event is not None:
  325. match = re.search(r"\.py\(.*\)", event.name)
  326. if match is None:
  327. event = event.parent
  328. continue
  329. return event.name
  330. return "No source code location found"
  331. # Provide an OSS workaround for cudagraphs + CUPTI issue
  332. # https://github.com/pytorch/pytorch/issues/75504
  333. # TODO(dberard) - deprecate / remove workaround for CUDA >= 12, when
  334. # we stop supporting older CUDA versions.
  335. def _init_for_cuda_graphs() -> None:
  336. from torch.autograd.profiler import profile
  337. with profile():
  338. pass
  339. @dataclass
  340. class TimelineEvent:
  341. """Represents an event in the profiler timeline."""
  342. timestamp: int
  343. event_type: Literal["start", "end", "regular"]
  344. marker_type: Literal["filename", "node"] | None
  345. identifier: str | int | None
  346. event: dict[str, Any]
  347. @dataclass
  348. class ContextStackEntry:
  349. """Represents a context (filename or node) in the stack."""
  350. context_type: Literal["filename", "node"]
  351. identifier: str | int
  352. metadata: dict | None
  353. tid: int | None = None # Thread ID associated with this context
  354. def map_recorded_events_to_aten_ops_with_stack_trace(traced_data):
  355. """
  356. Maps recorded profiler events to their corresponding fx nodes and adds stack traces.
  357. Builds a timeline of all events (regular ops and FX markers for filenames/nodes),
  358. sorts by timestamp, then processes chronologically while maintaining a context stack of active
  359. filename/node scopes. Regular events are augmented with stack traces and node names from the
  360. innermost active context. Runtime is O(n log n) for n events.
  361. Args:
  362. traced_data: Json of profiler events from Chrome trace
  363. Returns:
  364. Dict mapping recorded event names to their aten operations with added stack traces
  365. """
  366. from torch.fx.traceback import _FX_METADATA_REGISTRY
  367. trace_events = traced_data.get("traceEvents", [])
  368. # Create event timeline
  369. event_timeline: list[TimelineEvent] = []
  370. def is_fx_marker_event(event):
  371. return (
  372. event.get("cat") == "cpu_op"
  373. and event.get("name", "").startswith("## ")
  374. and event.get("name", "").endswith(" ##")
  375. )
  376. def append_fx_marker_event(event_type, identifier, event):
  377. start_ts = event["ts"]
  378. end_ts = start_ts + event["dur"]
  379. event_timeline.append(
  380. TimelineEvent(start_ts, "start", event_type, identifier, event)
  381. )
  382. event_timeline.append(
  383. TimelineEvent(end_ts, "end", event_type, identifier, event)
  384. )
  385. for event in trace_events:
  386. if "ts" not in event or "dur" not in event:
  387. continue
  388. if is_fx_marker_event(event):
  389. content = event["name"][3:-3]
  390. if content.endswith(".py"):
  391. append_fx_marker_event("filename", content, event)
  392. else:
  393. try:
  394. node_index = int(content)
  395. except ValueError:
  396. pass
  397. append_fx_marker_event("node", node_index, event) # type: ignore[possibly-undefined]
  398. else:
  399. # Regular event that needs augmentation
  400. start_ts = event["ts"]
  401. event_timeline.append(TimelineEvent(start_ts, "regular", None, None, event))
  402. # Sort by timestamp
  403. event_timeline.sort(key=lambda x: x.timestamp)
  404. # Process events in chronological order with a stack
  405. context_stack: list[ContextStackEntry] = []
  406. # Invariant: all start event has a corresponding end event
  407. for timeline_event in event_timeline:
  408. match timeline_event.event_type:
  409. case "start":
  410. assert timeline_event.identifier is not None
  411. if timeline_event.marker_type == "filename":
  412. assert isinstance(timeline_event.identifier, str)
  413. # Push filename context - query metadata registry on-demand
  414. metadata = _FX_METADATA_REGISTRY.get(timeline_event.identifier)
  415. tid = timeline_event.event.get("tid")
  416. context_stack.append(
  417. ContextStackEntry(
  418. "filename", timeline_event.identifier, metadata, tid
  419. )
  420. )
  421. elif timeline_event.marker_type == "node":
  422. # Find the current filename from stack
  423. current_file_metadata = None
  424. tid = timeline_event.event.get("tid")
  425. for ctx_entry in reversed(context_stack):
  426. if (
  427. ctx_entry.context_type == "filename"
  428. and ctx_entry.tid == tid
  429. ):
  430. current_file_metadata = ctx_entry.metadata
  431. break
  432. if current_file_metadata:
  433. node_metadata = current_file_metadata.get("node_metadata", {})
  434. if timeline_event.identifier in node_metadata:
  435. node_meta: dict | None = node_metadata[
  436. timeline_event.identifier
  437. ]
  438. context_stack.append(
  439. ContextStackEntry(
  440. "node", timeline_event.identifier, node_meta, tid
  441. )
  442. )
  443. case "end":
  444. # Pop from stack - search backwards to find matching context
  445. for i in range(len(context_stack) - 1, -1, -1):
  446. ctx_entry = context_stack[i]
  447. if (
  448. timeline_event.marker_type == ctx_entry.context_type
  449. and timeline_event.identifier == ctx_entry.identifier
  450. ):
  451. context_stack.pop(i)
  452. break
  453. case "regular":
  454. # Apply metadata from current context stack
  455. # Find the most specific context (node takes precedence over filename)
  456. # Only augment events with the same tid as the file/node event matched
  457. current_stack_trace = None
  458. current_node_name = None
  459. event_tid = timeline_event.event.get("tid")
  460. for ctx_entry in reversed(context_stack):
  461. # Only apply metadata from contexts with matching tid
  462. if ctx_entry.tid == event_tid:
  463. if ctx_entry.context_type == "node" and ctx_entry.metadata:
  464. current_stack_trace = ctx_entry.metadata.get(
  465. "stack_trace", "No model stack trace available"
  466. )
  467. current_node_name = ctx_entry.metadata.get("name", "")
  468. # Do we want to only attach the stack trace of the lowest node or stack trace of all nodes
  469. # if nodes are nested, e.g. in nested graph modules
  470. break
  471. # Augment the event
  472. if current_stack_trace or current_node_name:
  473. args = timeline_event.event.setdefault("args", {})
  474. if current_stack_trace:
  475. args["stack_trace"] = current_stack_trace
  476. if current_node_name:
  477. args["node_name"] = current_node_name