systrace-extract-startup.py 18 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594
  1. #!/usr/bin/env python
  2. # Copyright 2018 The Chromium Authors. All rights reserved.
  3. # Use of this source code is governed by a BSD-style license that can be
  4. # found in the LICENSE file.
  5. # This script parses result of build/android/adb_profile_chrome_startup and
  6. # prints various information.
  7. from __future__ import print_function
  8. import argparse
  9. import collections
  10. import glob
  11. import itertools
  12. import json
  13. import os
  14. import re
  15. def HumanSortingKey(string):
  16. # From https://goo.gl/65xrva
  17. def _ToInt(string):
  18. return int(string) if string.isdigit() else string
  19. return [_ToInt(c) for c in re.split('(\d+)', string)]
  20. class LogIndenter(object):
  21. _indentation = 0
  22. def __init__(self, message=None, *arguments):
  23. self._indented = False
  24. if message is not None:
  25. log(message, *arguments)
  26. def __enter__(self):
  27. self.indent()
  28. return self
  29. def __exit__(self, type, value, traceback):
  30. self.unindent()
  31. def indent(self):
  32. if not self._indented:
  33. LogIndenter._indentation += 1
  34. self._indented = True
  35. def unindent(self):
  36. if self._indented:
  37. LogIndenter._indentation -= 1
  38. self._indented = False
  39. @classmethod
  40. def indentation(self):
  41. return LogIndenter._indentation
  42. def log(message, *arguments):
  43. if not message:
  44. print()
  45. return
  46. if arguments:
  47. message = message.format(*arguments)
  48. if LogIndenter.indentation() > 0:
  49. message = ' ' * LogIndenter.indentation() + message
  50. print(message)
  51. def ParseTraceDatas(trace_file_path):
  52. start_tag = re.compile(
  53. '^\s*<script class="trace-data" type="application/text">$')
  54. end_tag = re.compile('^(?P<line>.*?)\s*</script>$')
  55. trace_datas = []
  56. current_trace_lines = None
  57. with open(trace_file_path) as trace_file:
  58. for line in trace_file:
  59. line = line.rstrip()
  60. if current_trace_lines is None:
  61. if start_tag.match(line):
  62. current_trace_lines = []
  63. else:
  64. match = end_tag.match(line)
  65. if match:
  66. current_trace_lines.append(match.group('line'))
  67. trace_datas.append('\n'.join(current_trace_lines))
  68. current_trace_lines = None
  69. else:
  70. current_trace_lines.append(line)
  71. return trace_datas
  72. class Event(object):
  73. PHASE_BEGIN = 'B'
  74. PHASE_END = 'E'
  75. PHASE_COMPLETE = 'X'
  76. PHASE_ASYNC_BEGIN = 'S'
  77. PHASE_ASYNC_END = 'F'
  78. def __init__(self, node):
  79. self._node = node
  80. @property
  81. def pid(self):
  82. return int(self._node['pid'])
  83. @property
  84. def tid(self):
  85. return int(self._node['tid'])
  86. @property
  87. def name(self):
  88. return self._node.get('name')
  89. @property
  90. def phase(self):
  91. return self._node['ph']
  92. @property
  93. def category(self):
  94. return self._node['cat']
  95. @property
  96. def timestamp_us(self):
  97. return long(self._node['ts'])
  98. @property
  99. def duration_us(self):
  100. return long(self._node['dur'])
  101. @property
  102. def args(self):
  103. return self._node['args']
  104. class EventInterval(object):
  105. def __init__(self, from_event=None, to_event=None):
  106. self.from_event = from_event
  107. self.to_event = to_event
  108. def SetFromEventOnce(self, from_event):
  109. if self.from_event is None:
  110. self.from_event = from_event
  111. def SetToEventOnce(self, to_event):
  112. if self.to_event is None:
  113. self.to_event = to_event
  114. def FormatAsMilliseconds(self):
  115. if not self.from_event:
  116. time_string = "[missing the start of of the interval]"
  117. elif not self.to_event:
  118. time_string = "[missing the end of the interval]"
  119. else:
  120. interval_us = self.to_event.timestamp_us - self.from_event.timestamp_us
  121. time_string = str(interval_us / 1000.0)
  122. return time_string
  123. def UpTo(self, other_iterval):
  124. return EventInterval(self.from_event, other_iterval.to_event)
  125. class Process(object):
  126. BROWSER_NAME = 'Browser'
  127. def __init__(self, pid):
  128. self.pid = pid
  129. self.name = None
  130. self.events_by_name = collections.defaultdict(list)
  131. self.time_ns_by_histogram = {}
  132. self.malloc_counter_by_name = {}
  133. # TODO: move these into Trace
  134. self.startup_interval = EventInterval()
  135. self.first_ui_interval = EventInterval()
  136. class Trace(object):
  137. def __init__(self, file_path):
  138. self.file_path = file_path
  139. self.process_by_pid = {}
  140. self.startup_event = None
  141. self.navigation_start_event = None
  142. # TODO: convert these to properties over events
  143. self.navigation_to_contentul_paint_interval = EventInterval()
  144. self.navigation_to_meaningful_paint_interval = EventInterval()
  145. self.navigation_to_commit_interval = None
  146. @property
  147. def startup_to_navigation_interval(self):
  148. return EventInterval(self.startup_event, self.navigation_start_event)
  149. def Finalize(self):
  150. self.startup_event = self.FindFirstEvent(*Trace.STARTUP_EVENT_NAMES)
  151. self.navigation_start_event = self.FindFirstEvent(
  152. Trace.NAVIGATION_START_EVENT_NAME)
  153. def _FindNavigationToCommitInterval():
  154. events = self.FindAllEvents(Trace.NAVIGATION_COMMIT_EVENT_NAME)
  155. interval = EventInterval()
  156. for event in events:
  157. if event.phase == Event.PHASE_ASYNC_BEGIN:
  158. interval.SetFromEventOnce(event)
  159. elif event.phase == Event.PHASE_ASYNC_END:
  160. interval.SetToEventOnce(event)
  161. return interval
  162. self.navigation_to_commit_interval = _FindNavigationToCommitInterval()
  163. def FindAllEvents(self, *names):
  164. events = []
  165. for process in self.process_by_pid.itervalues():
  166. for name in names:
  167. process_events = process.events_by_name.get(name)
  168. if process_events:
  169. events.extend(process_events)
  170. events.sort(key=lambda e: e.timestamp_us)
  171. return events
  172. def FindFirstEvent(self, *names):
  173. events = self.FindAllEvents(*names)
  174. return events[0] if events else None
  175. NAVIGATION_START_EVENT_NAME = 'NavigationTiming navigationStart'
  176. NAVIGATION_COMMIT_EVENT_NAME = 'Navigation StartToCommit'
  177. STARTUP_EVENT_NAMES = [
  178. 'Startup.BrowserMainEntryPoint', 'ChromeApplication.onCreate',
  179. 'ContentShellApplication.onCreate'
  180. ]
  181. def ParseTrace(file_path):
  182. trace_datas = ParseTraceDatas(file_path)
  183. if not trace_datas:
  184. raise Exception("The file doesn't have any trace-data elements.")
  185. trace_json = None
  186. for trace_data in trace_datas:
  187. try:
  188. trace_json = json.loads(trace_data)
  189. except ValueError:
  190. continue
  191. if not trace_json:
  192. raise Exception("Couldn't parse trace-data json.")
  193. trace = Trace(file_path)
  194. for event_node in trace_json['traceEvents']:
  195. event = Event(event_node)
  196. pid = event.pid
  197. process = trace.process_by_pid.get(event.pid)
  198. if not process:
  199. process = Process(pid)
  200. trace.process_by_pid[pid] = process
  201. name = event.name
  202. if not name:
  203. continue
  204. process.events_by_name[name].append(event)
  205. phase = event.phase
  206. category = event.category
  207. if name == 'process_name':
  208. process.name = event.args['name']
  209. if (category == 'disabled-by-default-uma-addtime' and
  210. name not in process.time_ns_by_histogram):
  211. process.time_ns_by_histogram[name] = int(event.args['value_ns'])
  212. if name in Trace.STARTUP_EVENT_NAMES:
  213. process.startup_interval.SetFromEventOnce(event)
  214. elif name == 'BenchmarkInstrumentation::ImplThreadRenderingStats':
  215. process.startup_interval.SetToEventOnce(event)
  216. if name == Trace.NAVIGATION_START_EVENT_NAME:
  217. trace.navigation_to_contentul_paint_interval.SetFromEventOnce(event)
  218. trace.navigation_to_meaningful_paint_interval.SetFromEventOnce(event)
  219. elif name == 'firstContentfulPaint':
  220. trace.navigation_to_contentul_paint_interval.SetToEventOnce(event)
  221. elif name == 'firstMeaningfulPaint':
  222. trace.navigation_to_meaningful_paint_interval.SetToEventOnce(event)
  223. if (name == 'AsyncInitializationActivity.onCreate()' and
  224. phase == Event.PHASE_END):
  225. process.first_ui_interval.SetFromEventOnce(event)
  226. elif name == 'ChromeBrowserInitializer.startChromeBrowserProcessesAsync':
  227. process.first_ui_interval.SetToEventOnce(event)
  228. if category == 'malloc' and name == 'malloc_counter':
  229. counter_name, counter_value = next(event.args.iteritems())
  230. process.malloc_counter_by_name[counter_name] = long(counter_value)
  231. trace.Finalize()
  232. return trace
  233. EventSummary = collections.namedtuple('EventSummary', [
  234. 'trace',
  235. 'event',
  236. 'startup_to_event_ms',
  237. 'navigation_to_event_ms',
  238. 'duration_ms'
  239. ])
  240. def SummarizeEvents(event_name_regex, trace, process):
  241. summaries = []
  242. def _AddSummary(event, start_us, duration_us):
  243. startup_to_event_ms = (
  244. None if trace.startup_event is None else
  245. (start_us - trace.startup_event.timestamp_us) / 1000.0)
  246. navigation_to_event_ms = (
  247. None if trace.navigation_start_event is None else
  248. (start_us - trace.navigation_start_event.timestamp_us) / 1000.0)
  249. summaries.append(EventSummary(
  250. trace, event, startup_to_event_ms, navigation_to_event_ms,
  251. duration_us / 1000.0))
  252. for name, events in process.events_by_name.iteritems():
  253. if event_name_regex.search(name):
  254. sorted_events = sorted(events,
  255. key=lambda e: (e.tid, e.timestamp_us))
  256. begin_event = None
  257. for event in sorted_events:
  258. if event.phase == Event.PHASE_COMPLETE:
  259. _AddSummary(event, event.timestamp_us, event.duration_us)
  260. elif (event.phase == Event.PHASE_BEGIN or
  261. event.phase == Event.PHASE_ASYNC_BEGIN):
  262. begin_event = event
  263. elif (event.phase == Event.PHASE_END or
  264. event.phase == Event.PHASE_ASYNC_END):
  265. if begin_event is not None:
  266. duration_us = event.timestamp_us - begin_event.timestamp_us
  267. _AddSummary(event, begin_event.timestamp_us, duration_us)
  268. begin_event = None
  269. return summaries
  270. def PrintReport(file_paths, options):
  271. # TODO: don't accumulate traces, build report on the fly
  272. traces = []
  273. for file_path in file_paths:
  274. log('Parsing {}...', file_path)
  275. try:
  276. traces.append(ParseTrace(file_path))
  277. except Exception as e:
  278. log('Oops: {}', e.message)
  279. log('Parsed {} trace(s).', len(traces))
  280. event_name_regex = None
  281. event_summaries_by_name = collections.defaultdict(list)
  282. if options.print_events:
  283. event_name_regex = re.compile(options.print_events)
  284. def _TraceSortingKey(trace):
  285. return HumanSortingKey(os.path.basename(trace.file_path))
  286. traces.sort(key=lambda t: _TraceSortingKey(t))
  287. if options.csv:
  288. separator = ','
  289. gap = ''
  290. else:
  291. separator = '\t'
  292. # Make it less likely for terminals to eat tabs when wrapping a line.
  293. gap = ' '
  294. table = [[
  295. 'File',
  296. 'Startup (ms)',
  297. 'StartupToNavigation (ms)',
  298. 'NavigationToCommit (ms)',
  299. 'NavigationToContentfulPaint (ms)',
  300. 'StartupToContentfulPaint (ms)',
  301. 'NavigationToMeaningfulPaint (ms)',
  302. 'StartupToMeaningfulPaint (ms)'
  303. ]]
  304. for trace in traces:
  305. browser_process = None
  306. for process in trace.process_by_pid.itervalues():
  307. if process.name == Process.BROWSER_NAME:
  308. browser_process = process
  309. break
  310. if browser_process is None:
  311. continue
  312. table.append([
  313. os.path.basename(trace.file_path),
  314. browser_process.startup_interval.FormatAsMilliseconds(),
  315. trace.startup_to_navigation_interval.FormatAsMilliseconds(),
  316. trace.navigation_to_commit_interval.FormatAsMilliseconds(),
  317. trace.navigation_to_contentul_paint_interval.FormatAsMilliseconds(),
  318. browser_process.startup_interval.UpTo(trace.navigation_to_contentul_paint_interval).\
  319. FormatAsMilliseconds(),
  320. trace.navigation_to_meaningful_paint_interval.FormatAsMilliseconds(),
  321. browser_process.startup_interval.UpTo(trace.navigation_to_meaningful_paint_interval).\
  322. FormatAsMilliseconds()
  323. ])
  324. if event_name_regex:
  325. event_summaries = SummarizeEvents(
  326. event_name_regex, trace, browser_process)
  327. for summary in event_summaries:
  328. event_summaries_by_name[summary.event.name].append(summary)
  329. for name, event_summaries in event_summaries_by_name.iteritems():
  330. table.append([])
  331. summaries_by_trace = collections.defaultdict(list)
  332. for summary in event_summaries:
  333. summaries_by_trace[summary.trace].append(summary)
  334. width = max(len(s) for s in summaries_by_trace.itervalues())
  335. summary_headers = [
  336. 'StartupToEvent (ms)',
  337. 'NavigationToEvent (ms)',
  338. 'Duration (ms)'
  339. ]
  340. table.append(
  341. [name] +
  342. ([gap] * len(summary_headers)) +
  343. list(itertools.chain.from_iterable(
  344. ['#{}'.format(i)] + [gap] * (len(summary_headers) - 1)
  345. for i in range(1, width))))
  346. table.append(
  347. ['File'] +
  348. summary_headers * width)
  349. trace_summaries = sorted(summaries_by_trace.iteritems(),
  350. key=lambda t_s: _TraceSortingKey(t_s[0]))
  351. for trace, summaries in trace_summaries:
  352. row = [os.path.basename(trace.file_path)]
  353. for summary in summaries:
  354. row += [
  355. (gap if summary.startup_to_event_ms is None
  356. else summary.startup_to_event_ms),
  357. (gap if summary.navigation_to_event_ms is None
  358. else summary.navigation_to_event_ms),
  359. summary.duration_ms
  360. ]
  361. table.append(row)
  362. print()
  363. print('\n'.join(separator.join(str(v) for v in row) for row in table))
  364. def PrintTrace(trace_file_path, options):
  365. trace = ParseTrace(trace_file_path)
  366. def _PrintInterval(name, interval):
  367. log('{} (ms): {}', name, interval.FormatAsMilliseconds())
  368. def _PrintHistogramTime(process, name):
  369. time_ns = process.time_ns_by_histogram.get(name)
  370. time_ms = None if time_ns is None else time_ns / 1e6
  371. if time_ms is not None or options.print_none_histograms:
  372. log('{} (ms): {}', name, time_ms)
  373. histogram_names = [
  374. 'Startup.FirstCommitNavigationTime3.ZoomedIn',
  375. 'MobileStartup.ToolbarFirstDrawTime.ChromeTabbedActivity',
  376. 'ChromeGeneratedCustomTab.IntentToFirstCommitNavigationTime2.ZoomedIn',
  377. 'CustomTabs.IntentToFirstCommitNavigationTime2.ZoomedIn',
  378. 'PageLoad.PaintTiming.NavigationToFirstPaint',
  379. 'PageLoad.PaintTiming.NavigationToFirstContentfulPaint',
  380. 'PageLoad.Experimental.PaintTiming.NavigationToFirstMeaningfulPaint',
  381. 'SessionRestore.ForegroundTabFirstPaint3',
  382. ]
  383. processes = sorted(trace.process_by_pid.itervalues(), key=lambda p: p.name)
  384. events_regex = None
  385. if options.print_events:
  386. events_regex = re.compile(options.print_events)
  387. for process in processes:
  388. log('{} timings:', process.name)
  389. indenter = LogIndenter()
  390. indenter.indent()
  391. if process.name == Process.BROWSER_NAME:
  392. _PrintInterval('Startup', process.startup_interval)
  393. _PrintInterval('StartupToNavigation',
  394. trace.startup_to_navigation_interval)
  395. _PrintInterval('NavigationToCommit', trace.navigation_to_commit_interval)
  396. _PrintInterval('NavigationToContentfulPaint',
  397. trace.navigation_to_contentul_paint_interval)
  398. _PrintInterval('StartupToContentfulPaint', process.startup_interval.UpTo(
  399. trace.navigation_to_contentul_paint_interval))
  400. _PrintInterval('NavigationToMeaningfulPaint',
  401. trace.navigation_to_meaningful_paint_interval)
  402. _PrintInterval('StartupToMeaningfulPaint', process.startup_interval.UpTo(
  403. trace.navigation_to_meaningful_paint_interval))
  404. if options.experimental:
  405. _PrintInterval('First UI interval', process.first_ui_interval)
  406. if process.malloc_counter_by_name:
  407. def _PrintMallocCounter(title, value_name, factor):
  408. value = process.malloc_counter_by_name.get(value_name)
  409. if value is not None:
  410. value /= factor
  411. log('{}: {}', title, value)
  412. log('Malloc counters:')
  413. with LogIndenter():
  414. _PrintMallocCounter('Total time (ms)', 'malloc_time_ns', 1000000)
  415. _PrintMallocCounter('Total allocated (KiB)', 'allocated_bytes', 1024)
  416. _PrintMallocCounter('Allocations', 'allocation_count', 1)
  417. _PrintMallocCounter('Frees', 'free_count', 1)
  418. for histogram_name in histogram_names:
  419. _PrintHistogramTime(process, histogram_name)
  420. if events_regex:
  421. event_summaries = SummarizeEvents(events_regex, trace, process)
  422. if event_summaries:
  423. with LogIndenter('Events matching "{}":', events_regex.pattern):
  424. for event_summary in event_summaries:
  425. with LogIndenter('{}:', event_summary.event.name):
  426. if event_summary.startup_to_event_ms is not None:
  427. log('StartupToEvent (ms): {}',
  428. event_summary.startup_to_event_ms)
  429. if event_summary.navigation_to_event_ms is not None:
  430. log('NavigationToEvent (ms): {}',
  431. event_summary.navigation_to_event_ms)
  432. log('Duration (ms): {}', event_summary.duration_ms)
  433. indenter.unindent()
  434. log('')
  435. def main():
  436. parser = argparse.ArgumentParser()
  437. parser.add_argument('file_or_glob')
  438. parser.add_argument('--print-none-histograms',
  439. help='Print histograms with None values.',
  440. default=False, action='store_true')
  441. # TODO: introduce a variant that takes a list of event names, as escaping
  442. # event names can be tedious.
  443. # TODO: match regex against '<index>|<event name>' to allow selecting
  444. # events by index (complicated for begin/end pairs).
  445. parser.add_argument('--print-events',
  446. help='Print events matching the specified regex.')
  447. parser.add_argument('--experimental',
  448. default=False, action='store_true',
  449. help='Enable experimental stuff.')
  450. parser.add_argument('--report',
  451. default=False, action='store_true',
  452. help='Present information as a tab-separated table.')
  453. parser.add_argument('--csv',
  454. default=False, action='store_true',
  455. help=('Separate report values by commas (not tabs).'))
  456. options = parser.parse_args()
  457. globbed = False
  458. if os.path.isfile(options.file_or_glob):
  459. trace_file_paths = [options.file_or_glob]
  460. else:
  461. globbed = True
  462. file_pattern = options.file_or_glob
  463. trace_file_paths = glob.glob(file_pattern)
  464. if not trace_file_paths:
  465. file_pattern += '*html'
  466. trace_file_paths = glob.glob(file_pattern)
  467. if not trace_file_paths:
  468. log("'{}' didn't match anything.", file_pattern)
  469. return
  470. log("'{}' matched {} file(s).", file_pattern, len(trace_file_paths))
  471. log('')
  472. if options.report:
  473. PrintReport(trace_file_paths, options)
  474. else:
  475. for file_path in trace_file_paths:
  476. if globbed:
  477. log('_' * len(file_path))
  478. log(file_path)
  479. log('')
  480. PrintTrace(file_path, options)
  481. if __name__ == '__main__':
  482. main()