profiler_util.py 34 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804805806807808809810811812813814815816817818819820821822823824825826827828829830831832833834835836837838839840841842843844845846847848849850851852853854855856857858859860861862863864865866867868869870871872873874875876877878879880881882883884885886887888889890891892893894895896897898899900901902903904905906907908909910
  1. import itertools
  2. import torch
  3. from torch.autograd import DeviceType
  4. from collections import defaultdict, namedtuple
  5. from operator import attrgetter
  6. from typing import Dict, List, Tuple, Optional
  7. import bisect
  8. import math
  9. class EventList(list):
  10. """A list of Events (for pretty printing)"""
  11. def __init__(self, *args, **kwargs):
  12. use_cuda = kwargs.pop('use_cuda', True)
  13. profile_memory = kwargs.pop('profile_memory', False)
  14. with_flops = kwargs.pop('with_flops', False)
  15. super(EventList, self).__init__(*args, **kwargs)
  16. self._use_cuda = use_cuda
  17. self._profile_memory = profile_memory
  18. self._tree_built = False
  19. self._with_flops = with_flops
  20. def _build_tree(self):
  21. self._populate_cpu_children()
  22. self._remove_dup_nodes()
  23. self._set_backward_stacktraces()
  24. self._tree_built = True
  25. def __str__(self):
  26. return self.table()
  27. def _remove_dup_nodes(self):
  28. while True:
  29. to_delete = set()
  30. for idx in range(len(self)):
  31. if (self[idx].cpu_parent is not None and
  32. self[idx].cpu_parent.name == self[idx].name and
  33. len(self[idx].cpu_parent.cpu_children) == 1):
  34. self[idx].cpu_parent.cpu_children = self[idx].cpu_children
  35. self[idx].cpu_parent.kernels = self[idx].kernels # lift kernels up
  36. for ch in self[idx].cpu_children:
  37. ch.cpu_parent = self[idx].cpu_parent
  38. to_delete.add(idx)
  39. if len(to_delete) == 0:
  40. break
  41. new_evts = [ev for ind, ev in enumerate(self) if ind not in to_delete]
  42. self.clear()
  43. self.extend(new_evts)
  44. def _populate_cpu_children(self):
  45. """Populates child events into each underlying FunctionEvent object.
  46. One event is a child of another if [s1, e1) is inside [s2, e2). Where
  47. s1 and e1 would be start and end of the child event's interval. And
  48. s2 and e2 start and end of the parent event's interval
  49. Example: In event list [[0, 10], [1, 3], [3, 4]] would have make [0, 10]
  50. be a parent of two other intervals.
  51. If for any reason two intervals intersect only partially, this function
  52. will not record a parent child relationship between then.
  53. """
  54. # Some events can be async (i.e. start and end on different threads),
  55. # since it's generally undefined how to attribute children ranges to
  56. # async ranges, we do not use them when calculating nested ranges and stats
  57. sync_events = [evt for evt in self if not evt.is_async and evt.device_type == DeviceType.CPU]
  58. events = sorted(
  59. sync_events,
  60. key=attrgetter("thread"),
  61. )
  62. # Group by both thread and node_id, so that events that happen to have
  63. # the same thread_id but are from different nodes aren't incorrectly
  64. # grouped together.
  65. threads = itertools.groupby(
  66. events, key=lambda event: (event.thread, event.node_id)
  67. )
  68. # For each thread we keep a stack of current nested parents.
  69. # We maintain the invariant that each interval is a subset of all other
  70. # intervals lower in the stack.
  71. #
  72. # First we sort the intervals by their start time. Then we iterate over them.
  73. # Every time we see a new interval we remove several parents from
  74. # the top until we restore the invariant. Then parent child relationship
  75. # if recorded if the stack is not empty.
  76. # Finally we add new interval to the list
  77. #
  78. # Algorithm has O(N * log(N)) complexity where N is number of
  79. # intervals
  80. for thread_id, thread_events in threads:
  81. thread_events_ = sorted(
  82. thread_events,
  83. key=lambda event: [event.time_range.start, -event.time_range.end],
  84. )
  85. current_events: List[FunctionEvent] = []
  86. cur_end = 0
  87. for event in thread_events_:
  88. while len(current_events) > 0:
  89. parent = current_events[-1]
  90. if event.time_range.start >= parent.time_range.end or \
  91. event.time_range.end > parent.time_range.end:
  92. # this can't be a parent
  93. current_events.pop()
  94. else:
  95. parent.append_cpu_child(event)
  96. assert (
  97. event.cpu_parent is None
  98. ), "There is already a CPU parent event for {}".format(
  99. event.key
  100. )
  101. event.set_cpu_parent(parent)
  102. break
  103. current_events.append(event)
  104. def _set_backward_stacktraces(self):
  105. def bw_parent(evt):
  106. if evt is None:
  107. return None
  108. elif evt.scope == 1: # BACKWARD_FUNCTION
  109. return evt
  110. else:
  111. return bw_parent(evt.cpu_parent)
  112. fwd_stacks = {}
  113. for evt in self:
  114. if bw_parent(evt) is None and evt.stack is not None:
  115. t = (evt.sequence_nr, evt.thread)
  116. if t not in fwd_stacks:
  117. fwd_stacks[t] = evt.stack
  118. for evt in self:
  119. p = bw_parent(evt)
  120. if p is not None:
  121. assert p.fwd_thread is not None
  122. t = (p.sequence_nr, p.fwd_thread)
  123. if t in fwd_stacks:
  124. evt.stack = fwd_stacks[t]
  125. else:
  126. evt.stack = []
  127. @property
  128. def self_cpu_time_total(self):
  129. return sum([event.self_cpu_time_total for event in self])
  130. def table(self, sort_by=None, row_limit=100, max_src_column_width=75, header=None, top_level_events_only=False):
  131. """Prints an EventList as a nicely formatted table.
  132. Args:
  133. sort_by (str, optional): Attribute used to sort entries. By default
  134. they are printed in the same order as they were registered.
  135. Valid keys include: ``cpu_time``, ``cuda_time``, ``cpu_time_total``,
  136. ``cuda_time_total``, ``cpu_memory_usage``, ``cuda_memory_usage``,
  137. ``self_cpu_memory_usage``, ``self_cuda_memory_usage``, ``count``.
  138. top_level_events_only(bool, optional): Boolean flag to determine the
  139. selection of events to display. If true, the profiler will only
  140. display events at top level like top-level invocation of python
  141. `lstm`, python `add` or other functions, nested events like low-level
  142. cpu/cuda ops events are omitted for profiler result readability.
  143. Returns:
  144. A string containing the table.
  145. """
  146. return _build_table(
  147. self,
  148. sort_by=sort_by,
  149. row_limit=row_limit,
  150. max_src_column_width=max_src_column_width,
  151. header=header,
  152. profile_memory=self._profile_memory,
  153. with_flops=self._with_flops,
  154. top_level_events_only=top_level_events_only)
  155. def export_chrome_trace(self, path):
  156. """Exports an EventList as a Chrome tracing tools file.
  157. The checkpoint can be later loaded and inspected under ``chrome://tracing`` URL.
  158. Args:
  159. path (str): Path where the trace will be written.
  160. """
  161. import os
  162. with open(path, 'w') as f:
  163. chrome_events = []
  164. next_id = 0
  165. # Use file IO over using json.dump since JSON dumping is very slow and
  166. # this technique is proven to give a 4x speedup.
  167. f.write("[")
  168. for evt in self:
  169. if evt.trace_name is None:
  170. continue
  171. f.write(
  172. '{"name": "%s", '
  173. '"ph": "X", '
  174. '"ts": %s, '
  175. '"dur": %s, '
  176. '"tid": %s, '
  177. '"pid": "CPU functions", '
  178. '"args": {}}, '
  179. % (
  180. evt.trace_name,
  181. evt.time_range.start,
  182. evt.time_range.elapsed_us(),
  183. evt.thread
  184. if not evt.is_remote
  185. else f'" node_id:{evt.node_id}, thread_id:{evt.thread} "',
  186. )
  187. )
  188. for k in evt.kernels:
  189. # 's' and 'f' draw Flow arrows from
  190. # the CPU launch to the GPU kernel
  191. f.write('{"name": "%s", '
  192. '"ph": "s", '
  193. '"ts": %s, '
  194. '"tid": %s, '
  195. '"pid": "CPU functions", '
  196. '"id": %s, '
  197. '"cat": "cpu_to_cuda", '
  198. '"args": {}}, ' % (evt.trace_name, evt.time_range.start,
  199. evt.thread, next_id))
  200. # Note: use torch.profiler to get device kernel trace
  201. next_id += 1
  202. if len(self) > 0:
  203. # remove trailing whitespace and comma
  204. f.seek(f.tell() - 2, os.SEEK_SET)
  205. f.truncate()
  206. f.write("]")
  207. def supported_export_stacks_metrics(self):
  208. return ["self_cpu_time_total", "self_cuda_time_total"]
  209. def export_stacks(self, path: str, metric: str):
  210. if metric not in self.supported_export_stacks_metrics():
  211. raise ValueError("metric should be one of: " + str(self.supported_export_stacks_metrics()))
  212. translate_table = str.maketrans(" ;\t\n", "____")
  213. with open(path, 'w') as f:
  214. for evt in self:
  215. if evt.stack and len(evt.stack) > 0:
  216. metric_value = getattr(evt, metric)
  217. if int(metric_value) > 0:
  218. stack_str = ""
  219. for entry in reversed(evt.stack):
  220. stack_str += entry.translate(translate_table)
  221. stack_str += ";"
  222. stack_str = stack_str[:-1] + " " + str(int(metric_value))
  223. f.write(stack_str + "\n")
  224. def key_averages(self, group_by_input_shapes=False, group_by_stack_n=0):
  225. """Averages all function events over their keys.
  226. Args:
  227. group_by_input_shapes: group entries by
  228. (event name, input shapes) rather than just event name.
  229. This is useful to see which input shapes contribute to the runtime
  230. the most and may help with size-specific optimizations or
  231. choosing the best candidates for quantization (aka fitting a roof line)
  232. group_by_stack_n: group by top n stack trace entries
  233. Returns:
  234. An EventList containing FunctionEventAvg objects.
  235. """
  236. assert self._tree_built
  237. stats: Dict[Tuple[str, ...], FunctionEventAvg] = defaultdict(FunctionEventAvg)
  238. def get_key(event, group_by_input_shapes, group_by_stack_n) -> Tuple[str, ...]:
  239. key = [str(event.key), str(event.node_id), str(event.device_type), str(event.is_legacy)]
  240. if group_by_input_shapes:
  241. key.append(str(event.input_shapes))
  242. if group_by_stack_n > 0:
  243. key += event.stack[:group_by_stack_n]
  244. return tuple(key)
  245. for evt in self:
  246. stats[get_key(evt, group_by_input_shapes, group_by_stack_n)].add(evt)
  247. avg_list = EventList(
  248. stats.values(),
  249. use_cuda=self._use_cuda,
  250. profile_memory=self._profile_memory,
  251. with_flops=self._with_flops)
  252. for evt in avg_list:
  253. evt.stack = evt.stack[:group_by_stack_n]
  254. if not group_by_input_shapes:
  255. evt.input_shapes = ""
  256. return avg_list
  257. def total_average(self):
  258. """Averages all events.
  259. Returns:
  260. A FunctionEventAvg object.
  261. """
  262. total_stat = FunctionEventAvg()
  263. for evt in self:
  264. total_stat += evt
  265. total_stat.key = None
  266. total_stat.key = 'Total'
  267. return total_stat
  268. def _format_time(time_us):
  269. """Defines how to format time in FunctionEvent"""
  270. US_IN_SECOND = 1000.0 * 1000.0
  271. US_IN_MS = 1000.0
  272. if time_us >= US_IN_SECOND:
  273. return '{:.3f}s'.format(time_us / US_IN_SECOND)
  274. if time_us >= US_IN_MS:
  275. return '{:.3f}ms'.format(time_us / US_IN_MS)
  276. return '{:.3f}us'.format(time_us)
  277. def _format_time_share(time_us, total_time_us):
  278. """Defines how to format time in FunctionEvent"""
  279. if total_time_us == 0:
  280. assert time_us == 0, "Expected time_us == 0 but got {}".format(time_us)
  281. return "NaN"
  282. return '{:.2f}%'.format(time_us * 100.0 / total_time_us)
  283. def _format_memory(nbytes):
  284. """Returns a formatted memory size string"""
  285. KB = 1024
  286. MB = 1024 * KB
  287. GB = 1024 * MB
  288. if (abs(nbytes) >= GB):
  289. return '{:.2f} Gb'.format(nbytes * 1.0 / GB)
  290. elif (abs(nbytes) >= MB):
  291. return '{:.2f} Mb'.format(nbytes * 1.0 / MB)
  292. elif (abs(nbytes) >= KB):
  293. return '{:.2f} Kb'.format(nbytes * 1.0 / KB)
  294. else:
  295. return str(nbytes) + ' b'
  296. def _attr_formatter(name):
  297. return property(lambda self: _format_time(getattr(self, name)))
  298. class FormattedTimesMixin(object):
  299. """Helpers for FunctionEvent and FunctionEventAvg.
  300. The subclass should define `*_time_total` and `count` attributes.
  301. """
  302. cpu_time_str = _attr_formatter('cpu_time')
  303. cuda_time_str = _attr_formatter('cuda_time')
  304. cpu_time_total_str = _attr_formatter('cpu_time_total')
  305. cuda_time_total_str = _attr_formatter('cuda_time_total')
  306. self_cpu_time_total_str = _attr_formatter('self_cpu_time_total')
  307. self_cuda_time_total_str = _attr_formatter('self_cuda_time_total')
  308. @property
  309. def cpu_time(self):
  310. return 0.0 if self.count == 0 else 1.0 * self.cpu_time_total / self.count # type: ignore[attr-defined]
  311. @property
  312. def cuda_time(self):
  313. return 0.0 if self.count == 0 else 1.0 * self.cuda_time_total / self.count # type: ignore[attr-defined]
  314. class Interval(object):
  315. def __init__(self, start, end):
  316. self.start = start
  317. self.end = end
  318. def elapsed_us(self):
  319. return self.end - self.start
  320. Kernel = namedtuple('Kernel', ['name', 'device', 'duration'])
  321. class FunctionEvent(FormattedTimesMixin):
  322. """Profiling information about a single function."""
  323. def __init__(
  324. self, id, name, thread, start_us, end_us, fwd_thread=None, input_shapes=None,
  325. stack=None, scope=0, cpu_memory_usage=0, cuda_memory_usage=0, is_async=False,
  326. is_remote=False, sequence_nr=-1, node_id=-1, device_type=DeviceType.CPU, device_index=0,
  327. is_legacy=False, flops=None, trace_name=None):
  328. self.id: int = id
  329. self.node_id: int = node_id
  330. self.name: str = name
  331. self.trace_name: str = trace_name
  332. self.time_range: Interval = Interval(start_us, end_us)
  333. self.thread: int = thread
  334. self.fwd_thread: Optional[int] = fwd_thread
  335. self.kernels: List[Kernel] = []
  336. self.count: int = 1
  337. self.cpu_children: List[FunctionEvent] = []
  338. self.cpu_parent: Optional[FunctionEvent] = None
  339. self.input_shapes: Tuple[int, ...] = input_shapes
  340. self.stack: List = stack
  341. self.scope: int = scope
  342. self.cpu_memory_usage: int = cpu_memory_usage
  343. self.cuda_memory_usage: int = cuda_memory_usage
  344. self.is_async: bool = is_async
  345. self.is_remote: bool = is_remote
  346. self.sequence_nr: int = sequence_nr
  347. self.device_type: DeviceType = device_type
  348. self.device_index: int = device_index
  349. self.is_legacy: bool = is_legacy
  350. self.flops: Optional[int] = flops
  351. def append_kernel(self, name, device, duration):
  352. assert self.device_type == DeviceType.CPU
  353. self.kernels.append(Kernel(name, device, duration))
  354. def append_cpu_child(self, child):
  355. """Append a CPU child of type FunctionEvent.
  356. One is supposed to append only direct children to the event to have
  357. correct self cpu time being reported.
  358. """
  359. assert(self.device_type == DeviceType.CPU)
  360. assert(isinstance(child, FunctionEvent))
  361. assert(child.device_type == DeviceType.CPU)
  362. self.cpu_children.append(child)
  363. def set_cpu_parent(self, parent):
  364. """Set the immediate CPU parent of type FunctionEvent
  365. One profiling FunctionEvent should have only one CPU parent such that
  366. the child's range interval is completely inside the parent's. We use
  367. this connection to determine the event is from top-level op or not.
  368. """
  369. assert(self.device_type == DeviceType.CPU)
  370. assert(isinstance(parent, FunctionEvent))
  371. assert(parent.device_type == DeviceType.CPU)
  372. self.cpu_parent = parent
  373. # Note: async events don't have children, are not used when computing 'self'
  374. # metrics of other events, have only total cpu time
  375. @property
  376. def self_cpu_memory_usage(self):
  377. if self.is_async or self.device_type != DeviceType.CPU:
  378. return 0
  379. return self.cpu_memory_usage - sum(
  380. [child.cpu_memory_usage for child in self.cpu_children]
  381. )
  382. @property
  383. def self_cuda_memory_usage(self):
  384. if self.is_async or self.device_type != DeviceType.CPU:
  385. return 0
  386. return self.cuda_memory_usage - sum(
  387. [child.cuda_memory_usage for child in self.cpu_children]
  388. )
  389. @property
  390. def self_cpu_time_total(self):
  391. if self.is_async or self.device_type != DeviceType.CPU:
  392. return 0
  393. return self.cpu_time_total - sum(
  394. [child.cpu_time_total for child in self.cpu_children]
  395. )
  396. @property
  397. def cuda_time_total(self):
  398. if self.is_async:
  399. return 0
  400. if self.device_type == DeviceType.CPU:
  401. if not self.is_legacy:
  402. # account for the kernels in the children ops
  403. return (sum(kinfo.duration for kinfo in self.kernels) +
  404. sum(ch.cuda_time_total for ch in self.cpu_children))
  405. else:
  406. # each legacy cpu events has a single (fake) kernel
  407. return sum(kinfo.duration for kinfo in self.kernels)
  408. else:
  409. assert self.device_type == DeviceType.CUDA
  410. return self.time_range.elapsed_us()
  411. @property
  412. def self_cuda_time_total(self):
  413. if self.is_async:
  414. return 0
  415. if self.device_type == DeviceType.CPU:
  416. return self.cuda_time_total - \
  417. sum([child.cuda_time_total for child in self.cpu_children])
  418. else:
  419. assert(self.device_type == DeviceType.CUDA)
  420. return self.cuda_time_total
  421. @property
  422. def cpu_time_total(self):
  423. if self.device_type == DeviceType.CPU:
  424. return self.time_range.elapsed_us()
  425. else:
  426. return 0
  427. @property
  428. def key(self):
  429. return self.name
  430. def __repr__(self):
  431. return (
  432. '<FunctionEvent id={} name={} device_type={} node_id={} cpu_time={} start_us={} end_us={} '
  433. 'cpu_children={} cuda_time={} name={} thread={} input_shapes={} '
  434. 'cpu_memory_usage={} cuda_memory_usage={} is_async={} is_remote={} seq_nr={} is_legacy={}>'.format(
  435. self.id,
  436. self.name,
  437. self.device_type,
  438. self.node_id,
  439. self.cpu_time_str,
  440. self.time_range.start,
  441. self.time_range.end,
  442. str([child.id for child in self.cpu_children]),
  443. self.cuda_time_str,
  444. self.name,
  445. self.thread,
  446. str(self.input_shapes),
  447. self.cpu_memory_usage,
  448. self.cuda_memory_usage,
  449. self.is_async,
  450. self.is_remote,
  451. self.sequence_nr,
  452. self.is_legacy,
  453. )
  454. )
  455. class FunctionEventAvg(FormattedTimesMixin):
  456. """Used to average stats over multiple FunctionEvent objects."""
  457. def __init__(self):
  458. self.key: Optional[str] = None
  459. self.count: int = 0
  460. self.node_id: int = 0
  461. self.is_async: bool = False
  462. self.is_remote: bool = False
  463. self.cpu_time_total: int = 0
  464. self.cuda_time_total: int = 0
  465. self.self_cpu_time_total: int = 0
  466. self.self_cuda_time_total: int = 0
  467. self.input_shapes: Optional[List[List[int]]] = None
  468. self.stack: Optional[List] = None
  469. self.scope: Optional[int] = None
  470. self.cpu_memory_usage: int = 0
  471. self.cuda_memory_usage: int = 0
  472. self.self_cpu_memory_usage: int = 0
  473. self.self_cuda_memory_usage: int = 0
  474. self.cpu_children: Optional[List[FunctionEvent]] = None
  475. self.cpu_parent: Optional[FunctionEvent] = None
  476. self.device_type: DeviceType = DeviceType.CPU
  477. self.is_legacy: bool = False
  478. self.flops: int = 0
  479. def add(self, other):
  480. if self.key is None:
  481. # First function being recorded as part of FunctionEventAvg, propagate
  482. # fields.
  483. self.key = other.key
  484. self.node_id = other.node_id
  485. self.is_async = other.is_async
  486. self.is_remote = other.is_remote
  487. self.cpu_parent = other.cpu_parent
  488. self.cpu_children = other.cpu_children
  489. self.input_shapes = other.input_shapes
  490. self.stack = other.stack
  491. self.scope = other.scope
  492. self.device_type = other.device_type
  493. self.is_legacy = other.is_legacy
  494. assert isinstance(other, (FunctionEvent, FunctionEventAvg))
  495. assert other.key == self.key
  496. self.cpu_time_total += other.cpu_time_total
  497. self.cuda_time_total += other.cuda_time_total
  498. self.self_cpu_time_total += other.self_cpu_time_total
  499. self.self_cuda_time_total += other.self_cuda_time_total
  500. self.cpu_memory_usage += other.cpu_memory_usage
  501. self.cuda_memory_usage += other.cuda_memory_usage
  502. self.self_cpu_memory_usage += other.self_cpu_memory_usage
  503. self.self_cuda_memory_usage += other.self_cuda_memory_usage
  504. self.count += other.count
  505. if self.flops is None:
  506. self.flops = other.flops
  507. elif other.flops is not None:
  508. self.flops += other.flops
  509. return self
  510. def __iadd__(self, other):
  511. return self.add(other)
  512. def __repr__(self):
  513. return (
  514. '<FunctionEventAvg key={} self_cpu_time={} cpu_time={} '
  515. ' self_cuda_time={} cuda_time={} input_shapes={} '
  516. 'cpu_memory_usage={} cuda_memory_usage={}>'.format(
  517. self.key,
  518. self.self_cpu_time_total_str,
  519. self.cpu_time_str,
  520. self.self_cuda_time_total_str,
  521. self.cuda_time_str,
  522. str(self.input_shapes),
  523. self.cpu_memory_usage,
  524. self.cuda_memory_usage,
  525. )
  526. )
  527. class StringTable(defaultdict):
  528. def __missing__(self, key):
  529. # manage cases like 't' (demangled to 'unsigned short') separately,
  530. # for now simply check the length to avoid unexpected results for
  531. # the short sequences
  532. self[key] = torch._C._demangle(key) if len(key) > 1 else key
  533. return self[key]
  534. class MemRecordsAcc:
  535. """Acceleration structure for accessing mem_records in interval"""
  536. def __init__(self, mem_records):
  537. self._mem_records = mem_records
  538. self._start_uses = []
  539. self._indices = []
  540. if len(mem_records) > 0:
  541. tmp = sorted([(r[0].start_us(), i) for i, r in enumerate(mem_records)])
  542. self._start_uses, self._indices = zip(*tmp)
  543. def in_interval(self, start_us, end_us):
  544. start_idx = bisect.bisect_left(self._start_uses, start_us)
  545. end_idx = bisect.bisect_right(self._start_uses, end_us)
  546. for i in range(start_idx, end_idx):
  547. yield self._mem_records[self._indices[i]]
  548. def _filter_stack_entry(entry):
  549. filtered_entries = [
  550. ("autograd/__init__", "_make_grads"),
  551. ("autograd/__init__", "backward"),
  552. ("torch/tensor", "backward"),
  553. ("_internal/common_utils", "prof_callable"),
  554. ("_internal/common_utils", "prof_func_call"),
  555. ("_internal/common_utils", "prof_meth_call"),
  556. ]
  557. return all([not (f[0] in entry and f[1] in entry) for f in filtered_entries])
  558. MEMORY_EVENT_NAME = "[memory]"
  559. def _filter_name(name):
  560. # ignoring the following utility ops
  561. filtered_out_names = [
  562. MEMORY_EVENT_NAME, # used only for the top-level memory events
  563. "profiler::_record_function_enter",
  564. "profiler::_record_function_enter_new",
  565. "profiler::_record_function_exit",
  566. "aten::is_leaf",
  567. "aten::output_nr",
  568. "aten::_version",
  569. ]
  570. return name in filtered_out_names
  571. # Demangles and optionally rewrites the provided event name,
  572. # with_wildcard - whether to replace certain numbered event names
  573. # with a wildcard name to aggregate them together in the profiler table
  574. # output
  575. def _rewrite_name(name, with_wildcard=False):
  576. string_table = StringTable()
  577. name = string_table[name]
  578. if with_wildcard:
  579. if name.startswith("ProfilerStep#"):
  580. name = "ProfilerStep*"
  581. return name
  582. def _build_table(
  583. events,
  584. sort_by=None,
  585. header=None,
  586. row_limit=100,
  587. max_src_column_width=75,
  588. with_flops=False,
  589. profile_memory=False,
  590. top_level_events_only=False):
  591. """Prints a summary of events (which can be a list of FunctionEvent or FunctionEventAvg)."""
  592. if len(events) == 0:
  593. return ""
  594. has_cuda_time = any([event.self_cuda_time_total > 0 for event in events])
  595. has_cuda_mem = any([event.self_cuda_memory_usage > 0 for event in events])
  596. has_input_shapes = any(
  597. [(event.input_shapes is not None and len(event.input_shapes) > 0) for event in events])
  598. if sort_by is not None:
  599. events = EventList(sorted(
  600. events, key=lambda evt: getattr(evt, sort_by), reverse=True
  601. ), use_cuda=has_cuda_time, profile_memory=profile_memory, with_flops=with_flops)
  602. MAX_NAME_COLUMN_WIDTH = 55
  603. name_column_width = max([len(evt.key) for evt in events]) + 4
  604. name_column_width = min(name_column_width, MAX_NAME_COLUMN_WIDTH)
  605. MAX_SHAPES_COLUMN_WIDTH = 80
  606. shapes_column_width = max([len(str(evt.input_shapes)) for evt in events]) + 4
  607. shapes_column_width = min(shapes_column_width, MAX_SHAPES_COLUMN_WIDTH)
  608. DEFAULT_COLUMN_WIDTH = 12
  609. flops_column_width = DEFAULT_COLUMN_WIDTH
  610. src_column_width = None
  611. stacks = []
  612. for evt in events:
  613. if evt.stack is not None and len(evt.stack) > 0:
  614. stacks.append(evt.stack)
  615. has_stack = len(stacks) > 0
  616. if has_stack:
  617. src_column_width = max([max([len(entry) for entry in stack]) for stack in stacks]) + 4
  618. src_column_width = min(src_column_width, max_src_column_width)
  619. headers = [
  620. 'Name',
  621. 'Self CPU %',
  622. 'Self CPU',
  623. 'CPU total %',
  624. 'CPU total',
  625. 'CPU time avg',
  626. ]
  627. if has_cuda_time:
  628. headers.extend([
  629. 'Self CUDA',
  630. 'Self CUDA %',
  631. 'CUDA total',
  632. 'CUDA time avg',
  633. ])
  634. if profile_memory:
  635. headers.extend([
  636. 'CPU Mem',
  637. 'Self CPU Mem',
  638. ])
  639. if has_cuda_mem:
  640. headers.extend([
  641. 'CUDA Mem',
  642. 'Self CUDA Mem',
  643. ])
  644. headers.append(
  645. '# of Calls'
  646. )
  647. # Only append Node ID if any event has a valid (>= 0) Node ID
  648. append_node_id = any([evt.node_id != -1 for evt in events])
  649. if append_node_id:
  650. headers.append('Node ID')
  651. # Have to use a list because nonlocal is Py3 only...
  652. SPACING_SIZE = 2
  653. row_format_lst = [""]
  654. header_sep_lst = [""]
  655. line_length_lst = [-SPACING_SIZE]
  656. MAX_STACK_ENTRY = 5
  657. def add_column(padding, text_dir='>'):
  658. row_format_lst[0] += '{: ' + text_dir + str(padding) + '}' + (' ' * SPACING_SIZE)
  659. header_sep_lst[0] += '-' * padding + (' ' * SPACING_SIZE)
  660. line_length_lst[0] += padding + SPACING_SIZE
  661. def auto_scale_flops(flops):
  662. flop_headers = [
  663. 'FLOPs',
  664. 'KFLOPs',
  665. 'MFLOPs',
  666. 'GFLOPs',
  667. 'TFLOPs',
  668. 'PFLOPs',
  669. ]
  670. assert flops > 0
  671. log_flops = max(0, min(math.log10(flops) / 3, float(len(flop_headers) - 1)))
  672. assert log_flops >= 0 and log_flops < len(flop_headers)
  673. return (pow(10, (math.floor(log_flops) * -3.0)), flop_headers[int(log_flops)])
  674. add_column(name_column_width)
  675. for _ in headers[1:]:
  676. add_column(DEFAULT_COLUMN_WIDTH)
  677. if has_input_shapes:
  678. headers.append('Input Shapes')
  679. add_column(shapes_column_width)
  680. if has_stack:
  681. headers.append('Source Location')
  682. add_column(src_column_width, text_dir='<')
  683. if with_flops:
  684. # Auto-scaling of flops header
  685. raw_flops = []
  686. for evt in events:
  687. if evt.flops > 0:
  688. raw_flops.append(evt.flops)
  689. if len(raw_flops) != 0:
  690. (flops_scale, flops_header) = auto_scale_flops(min(raw_flops))
  691. headers.append('Total {}'.format(flops_header))
  692. add_column(flops_column_width)
  693. else:
  694. with_flops = False # can't find any valid flops
  695. row_format = row_format_lst[0]
  696. header_sep = header_sep_lst[0]
  697. line_length = line_length_lst[0]
  698. add_column = None # type: ignore[assignment]
  699. # Have to use a list because nonlocal is Py3 only...
  700. result = []
  701. def append(s):
  702. result.append(s)
  703. result.append('\n') # Yes, newline after the end as well
  704. sum_self_cpu_time_total = sum([event.self_cpu_time_total for event in events])
  705. sum_self_cuda_time_total = 0
  706. for evt in events:
  707. if evt.device_type == DeviceType.CPU:
  708. # in legacy profiler, kernel info is stored in cpu events
  709. if evt.is_legacy:
  710. sum_self_cuda_time_total += evt.self_cuda_time_total
  711. elif evt.device_type == DeviceType.CUDA:
  712. # in kineto profiler, there're events with the correct device type (e.g. CUDA)
  713. sum_self_cuda_time_total += evt.self_cuda_time_total
  714. # Actual printing
  715. if header is not None:
  716. append('=' * line_length)
  717. append(header)
  718. if top_level_events_only:
  719. append('=' * line_length)
  720. append('This report only display top-level ops statistics')
  721. append(header_sep)
  722. append(row_format.format(*headers))
  723. append(header_sep)
  724. def trim_path(path, src_column_width):
  725. if len(path) > src_column_width:
  726. offset = len(path) - src_column_width
  727. path = path[offset:]
  728. if len(path) > 3:
  729. path = "..." + path[3:]
  730. return path
  731. event_limit = 0
  732. for evt in events:
  733. if event_limit == row_limit:
  734. break
  735. if top_level_events_only and evt.cpu_parent is not None:
  736. continue
  737. else:
  738. event_limit += 1
  739. name = evt.key
  740. if len(name) >= MAX_NAME_COLUMN_WIDTH - 3:
  741. name = name[:(MAX_NAME_COLUMN_WIDTH - 3)] + "..."
  742. row_values = [
  743. name,
  744. # Self CPU total %, 0 for async events.
  745. _format_time_share(evt.self_cpu_time_total, sum_self_cpu_time_total),
  746. evt.self_cpu_time_total_str, # Self CPU total
  747. # CPU total %, 0 for async events.
  748. _format_time_share(evt.cpu_time_total, sum_self_cpu_time_total) if not evt.is_async else 0,
  749. evt.cpu_time_total_str, # CPU total
  750. evt.cpu_time_str, # CPU time avg
  751. ]
  752. if has_cuda_time:
  753. row_values.extend([
  754. evt.self_cuda_time_total_str,
  755. # CUDA time total %
  756. _format_time_share(evt.self_cuda_time_total, sum_self_cuda_time_total),
  757. evt.cuda_time_total_str,
  758. evt.cuda_time_str, # Cuda time avg
  759. ])
  760. if profile_memory:
  761. row_values.extend([
  762. # CPU Mem Total
  763. _format_memory(evt.cpu_memory_usage),
  764. # Self CPU Mem Total
  765. _format_memory(evt.self_cpu_memory_usage),
  766. ])
  767. if has_cuda_mem:
  768. row_values.extend([
  769. # CUDA Mem Total
  770. _format_memory(evt.cuda_memory_usage),
  771. # Self CUDA Mem Total
  772. _format_memory(evt.self_cuda_memory_usage),
  773. ])
  774. row_values.append(
  775. evt.count, # Number of calls
  776. )
  777. if append_node_id:
  778. row_values.append(evt.node_id)
  779. if has_input_shapes:
  780. row_values.append(str(evt.input_shapes)[:shapes_column_width])
  781. if with_flops:
  782. if evt.flops <= 0:
  783. row_values.append("--")
  784. else:
  785. row_values.append('{0:8.3f}'.format(evt.flops * flops_scale))
  786. if has_stack:
  787. src_field = ""
  788. if len(evt.stack) > 0:
  789. src_field = trim_path(evt.stack[0], src_column_width)
  790. row_values.append(src_field)
  791. append(row_format.format(*row_values))
  792. if has_stack:
  793. empty_headers = [""] * (len(headers) - 1)
  794. for entry in evt.stack[1:MAX_STACK_ENTRY]:
  795. append(row_format.format(*(empty_headers + [trim_path(entry, src_column_width)])))
  796. empty_headers.append("")
  797. append(row_format.format(*empty_headers))
  798. append(header_sep)
  799. append("Self CPU time total: {}".format(_format_time(sum_self_cpu_time_total)))
  800. if has_cuda_time:
  801. append("Self CUDA time total: {}".format(_format_time(sum_self_cuda_time_total)))
  802. return ''.join(result)