ll_prof.py 32 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804805806807808809810811812813814815816817818819820821822823824825826827828829830831832833834835836837838839840841842843844845846847848849850851852853854855856857858859860861862863864865866867868869870871872873874875876877878879880881882883884885886887888889890891892893894895896897898899900901902903904905906907908909910911912913914915916917918919920921922923924925926927928929930931932933934935936937938939940941942943944945946947948949950951952953954955956957958959960961962963964965966967968969970971972973974975976977978979980981982983984985986987988989990991992
  1. #!/usr/bin/env python
  2. #
  3. # Copyright 2012 the V8 project authors. All rights reserved.
  4. # Redistribution and use in source and binary forms, with or without
  5. # modification, are permitted provided that the following conditions are
  6. # met:
  7. #
  8. # * Redistributions of source code must retain the above copyright
  9. # notice, this list of conditions and the following disclaimer.
  10. # * Redistributions in binary form must reproduce the above
  11. # copyright notice, this list of conditions and the following
  12. # disclaimer in the documentation and/or other materials provided
  13. # with the distribution.
  14. # * Neither the name of Google Inc. nor the names of its
  15. # contributors may be used to endorse or promote products derived
  16. # from this software without specific prior written permission.
  17. #
  18. # THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
  19. # "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
  20. # LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
  21. # A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
  22. # OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
  23. # SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
  24. # LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
  25. # DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
  26. # THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
  27. # (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
  28. # OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
  29. # for py2/py3 compatibility
  30. from __future__ import print_function
  31. import bisect
  32. import collections
  33. import ctypes
  34. import disasm
  35. import mmap
  36. import optparse
  37. import os
  38. import re
  39. import subprocess
  40. import sys
  41. import time
  42. USAGE="""usage: %prog [OPTION]...
  43. Analyses V8 and perf logs to produce profiles.
  44. Perf logs can be collected using a command like:
  45. $ perf record -R -e cycles -c 10000 -f -i ./d8 bench.js --ll-prof
  46. # -R: collect all data
  47. # -e cycles: use cpu-cycles event (run "perf list" for details)
  48. # -c 10000: write a sample after each 10000 events
  49. # -f: force output file overwrite
  50. # -i: limit profiling to our process and the kernel
  51. # --ll-prof shell flag enables the right V8 logs
  52. This will produce a binary trace file (perf.data) that %prog can analyse.
  53. IMPORTANT:
  54. The kernel has an internal maximum for events per second, it is 100K by
  55. default. That's not enough for "-c 10000". Set it to some higher value:
  56. $ echo 10000000 | sudo tee /proc/sys/kernel/perf_event_max_sample_rate
  57. You can also make the warning about kernel address maps go away:
  58. $ echo 0 | sudo tee /proc/sys/kernel/kptr_restrict
  59. We have a convenience script that handles all of the above for you:
  60. $ tools/run-llprof.sh ./d8 bench.js
  61. Examples:
  62. # Print flat profile with annotated disassembly for the 10 top
  63. # symbols. Use default log names.
  64. $ %prog --disasm-top=10
  65. # Print flat profile with annotated disassembly for all used symbols.
  66. # Use default log names and include kernel symbols into analysis.
  67. $ %prog --disasm-all --kernel
  68. # Print flat profile. Use custom log names.
  69. $ %prog --log=foo.log --trace=foo.data
  70. """
  71. JS_ORIGIN = "js"
  72. class Code(object):
  73. """Code object."""
  74. _id = 0
  75. UNKNOWN = 0
  76. V8INTERNAL = 1
  77. FULL_CODEGEN = 2
  78. OPTIMIZED = 3
  79. def __init__(self, name, start_address, end_address, origin, origin_offset):
  80. self.id = Code._id
  81. Code._id += 1
  82. self.name = name
  83. self.other_names = None
  84. self.start_address = start_address
  85. self.end_address = end_address
  86. self.origin = origin
  87. self.origin_offset = origin_offset
  88. self.self_ticks = 0
  89. self.self_ticks_map = None
  90. self.callee_ticks = None
  91. if name.startswith("LazyCompile:*"):
  92. self.codetype = Code.OPTIMIZED
  93. elif name.startswith("LazyCompile:"):
  94. self.codetype = Code.FULL_CODEGEN
  95. elif name.startswith("v8::internal::"):
  96. self.codetype = Code.V8INTERNAL
  97. else:
  98. self.codetype = Code.UNKNOWN
  99. def AddName(self, name):
  100. assert self.name != name
  101. if self.other_names is None:
  102. self.other_names = [name]
  103. return
  104. if not name in self.other_names:
  105. self.other_names.append(name)
  106. def FullName(self):
  107. if self.other_names is None:
  108. return self.name
  109. self.other_names.sort()
  110. return "%s (aka %s)" % (self.name, ", ".join(self.other_names))
  111. def IsUsed(self):
  112. return self.self_ticks > 0 or self.callee_ticks is not None
  113. def Tick(self, pc):
  114. self.self_ticks += 1
  115. if self.self_ticks_map is None:
  116. self.self_ticks_map = collections.defaultdict(lambda: 0)
  117. offset = pc - self.start_address
  118. self.self_ticks_map[offset] += 1
  119. def CalleeTick(self, callee):
  120. if self.callee_ticks is None:
  121. self.callee_ticks = collections.defaultdict(lambda: 0)
  122. self.callee_ticks[callee] += 1
  123. def PrintAnnotated(self, arch, options):
  124. if self.self_ticks_map is None:
  125. ticks_map = []
  126. else:
  127. ticks_map = self.self_ticks_map.items()
  128. # Convert the ticks map to offsets and counts arrays so that later
  129. # we can do binary search in the offsets array.
  130. ticks_map.sort(key=lambda t: t[0])
  131. ticks_offsets = [t[0] for t in ticks_map]
  132. ticks_counts = [t[1] for t in ticks_map]
  133. # Get a list of disassembled lines and their addresses.
  134. lines = self._GetDisasmLines(arch, options)
  135. if len(lines) == 0:
  136. return
  137. # Print annotated lines.
  138. address = lines[0][0]
  139. total_count = 0
  140. for i in range(len(lines)):
  141. start_offset = lines[i][0] - address
  142. if i == len(lines) - 1:
  143. end_offset = self.end_address - self.start_address
  144. else:
  145. end_offset = lines[i + 1][0] - address
  146. # Ticks (reported pc values) are not always precise, i.e. not
  147. # necessarily point at instruction starts. So we have to search
  148. # for ticks that touch the current instruction line.
  149. j = bisect.bisect_left(ticks_offsets, end_offset)
  150. count = 0
  151. for offset, cnt in reversed(zip(ticks_offsets[:j], ticks_counts[:j])):
  152. if offset < start_offset:
  153. break
  154. count += cnt
  155. total_count += count
  156. percent = 100.0 * count / self.self_ticks
  157. offset = lines[i][0]
  158. if percent >= 0.01:
  159. # 5 spaces for tick count
  160. # 1 space following
  161. # 1 for '|'
  162. # 1 space following
  163. # 6 for the percentage number, incl. the '.'
  164. # 1 for the '%' sign
  165. # => 15
  166. print("%5d | %6.2f%% %x(%d): %s" % (count, percent, offset, offset, lines[i][1]))
  167. else:
  168. print("%s %x(%d): %s" % (" " * 15, offset, offset, lines[i][1]))
  169. print()
  170. assert total_count == self.self_ticks, \
  171. "Lost ticks (%d != %d) in %s" % (total_count, self.self_ticks, self)
  172. def __str__(self):
  173. return "%s [0x%x, 0x%x) size: %d origin: %s" % (
  174. self.name,
  175. self.start_address,
  176. self.end_address,
  177. self.end_address - self.start_address,
  178. self.origin)
  179. def _GetDisasmLines(self, arch, options):
  180. if self.origin == JS_ORIGIN:
  181. inplace = False
  182. filename = options.log + ".ll"
  183. else:
  184. inplace = True
  185. filename = self.origin
  186. return disasm.GetDisasmLines(filename,
  187. self.origin_offset,
  188. self.end_address - self.start_address,
  189. arch,
  190. inplace)
  191. class CodePage(object):
  192. """Group of adjacent code objects."""
  193. SHIFT = 20 # 1M pages
  194. SIZE = (1 << SHIFT)
  195. MASK = ~(SIZE - 1)
  196. @staticmethod
  197. def PageAddress(address):
  198. return address & CodePage.MASK
  199. @staticmethod
  200. def PageId(address):
  201. return address >> CodePage.SHIFT
  202. @staticmethod
  203. def PageAddressFromId(id):
  204. return id << CodePage.SHIFT
  205. def __init__(self, address):
  206. self.address = address
  207. self.code_objects = []
  208. def Add(self, code):
  209. self.code_objects.append(code)
  210. def Remove(self, code):
  211. self.code_objects.remove(code)
  212. def Find(self, pc):
  213. code_objects = self.code_objects
  214. for i, code in enumerate(code_objects):
  215. if code.start_address <= pc < code.end_address:
  216. code_objects[0], code_objects[i] = code, code_objects[0]
  217. return code
  218. return None
  219. def __iter__(self):
  220. return self.code_objects.__iter__()
  221. class CodeMap(object):
  222. """Code object map."""
  223. def __init__(self):
  224. self.pages = {}
  225. self.min_address = 1 << 64
  226. self.max_address = -1
  227. def Add(self, code, max_pages=-1):
  228. page_id = CodePage.PageId(code.start_address)
  229. limit_id = CodePage.PageId(code.end_address + CodePage.SIZE - 1)
  230. pages = 0
  231. while page_id < limit_id:
  232. if max_pages >= 0 and pages > max_pages:
  233. print("Warning: page limit (%d) reached for %s [%s]" % (
  234. max_pages, code.name, code.origin), file=sys.stderr)
  235. break
  236. if page_id in self.pages:
  237. page = self.pages[page_id]
  238. else:
  239. page = CodePage(CodePage.PageAddressFromId(page_id))
  240. self.pages[page_id] = page
  241. page.Add(code)
  242. page_id += 1
  243. pages += 1
  244. self.min_address = min(self.min_address, code.start_address)
  245. self.max_address = max(self.max_address, code.end_address)
  246. def Remove(self, code):
  247. page_id = CodePage.PageId(code.start_address)
  248. limit_id = CodePage.PageId(code.end_address + CodePage.SIZE - 1)
  249. removed = False
  250. while page_id < limit_id:
  251. if page_id not in self.pages:
  252. page_id += 1
  253. continue
  254. page = self.pages[page_id]
  255. page.Remove(code)
  256. removed = True
  257. page_id += 1
  258. return removed
  259. def AllCode(self):
  260. for page in self.pages.itervalues():
  261. for code in page:
  262. if CodePage.PageAddress(code.start_address) == page.address:
  263. yield code
  264. def UsedCode(self):
  265. for code in self.AllCode():
  266. if code.IsUsed():
  267. yield code
  268. def Print(self):
  269. for code in self.AllCode():
  270. print(code)
  271. def Find(self, pc):
  272. if pc < self.min_address or pc >= self.max_address:
  273. return None
  274. page_id = CodePage.PageId(pc)
  275. if page_id not in self.pages:
  276. return None
  277. return self.pages[page_id].Find(pc)
  278. class CodeInfo(object):
  279. """Generic info about generated code objects."""
  280. def __init__(self, arch, header_size):
  281. self.arch = arch
  282. self.header_size = header_size
  283. class LogReader(object):
  284. """V8 low-level (binary) log reader."""
  285. _ARCH_TO_POINTER_TYPE_MAP = {
  286. "ia32": ctypes.c_uint32,
  287. "arm": ctypes.c_uint32,
  288. "mips": ctypes.c_uint32,
  289. "x64": ctypes.c_uint64,
  290. "arm64": ctypes.c_uint64
  291. }
  292. _CODE_CREATE_TAG = "C"
  293. _CODE_MOVE_TAG = "M"
  294. _CODE_MOVING_GC_TAG = "G"
  295. def __init__(self, log_name, code_map):
  296. self.log_file = open(log_name, "r")
  297. self.log = mmap.mmap(self.log_file.fileno(), 0, mmap.MAP_PRIVATE)
  298. self.log_pos = 0
  299. self.code_map = code_map
  300. self.arch = self.log[:self.log.find("\0")]
  301. self.log_pos += len(self.arch) + 1
  302. assert self.arch in LogReader._ARCH_TO_POINTER_TYPE_MAP, \
  303. "Unsupported architecture %s" % self.arch
  304. pointer_type = LogReader._ARCH_TO_POINTER_TYPE_MAP[self.arch]
  305. self.code_create_struct = LogReader._DefineStruct([
  306. ("name_size", ctypes.c_int32),
  307. ("code_address", pointer_type),
  308. ("code_size", ctypes.c_int32)])
  309. self.code_move_struct = LogReader._DefineStruct([
  310. ("from_address", pointer_type),
  311. ("to_address", pointer_type)])
  312. self.code_delete_struct = LogReader._DefineStruct([
  313. ("address", pointer_type)])
  314. def ReadUpToGC(self):
  315. while self.log_pos < self.log.size():
  316. tag = self.log[self.log_pos]
  317. self.log_pos += 1
  318. if tag == LogReader._CODE_MOVING_GC_TAG:
  319. return
  320. if tag == LogReader._CODE_CREATE_TAG:
  321. event = self.code_create_struct.from_buffer(self.log, self.log_pos)
  322. self.log_pos += ctypes.sizeof(event)
  323. start_address = event.code_address
  324. end_address = start_address + event.code_size
  325. name = self.log[self.log_pos:self.log_pos + event.name_size]
  326. origin = JS_ORIGIN
  327. self.log_pos += event.name_size
  328. origin_offset = self.log_pos
  329. self.log_pos += event.code_size
  330. code = Code(name, start_address, end_address, origin, origin_offset)
  331. conficting_code = self.code_map.Find(start_address)
  332. if conficting_code:
  333. if not (conficting_code.start_address == code.start_address and
  334. conficting_code.end_address == code.end_address):
  335. self.code_map.Remove(conficting_code)
  336. else:
  337. LogReader._HandleCodeConflict(conficting_code, code)
  338. # TODO(vitalyr): this warning is too noisy because of our
  339. # attempts to reconstruct code log from the snapshot.
  340. # print >>sys.stderr, \
  341. # "Warning: Skipping duplicate code log entry %s" % code
  342. continue
  343. self.code_map.Add(code)
  344. continue
  345. if tag == LogReader._CODE_MOVE_TAG:
  346. event = self.code_move_struct.from_buffer(self.log, self.log_pos)
  347. self.log_pos += ctypes.sizeof(event)
  348. old_start_address = event.from_address
  349. new_start_address = event.to_address
  350. if old_start_address == new_start_address:
  351. # Skip useless code move entries.
  352. continue
  353. code = self.code_map.Find(old_start_address)
  354. if not code:
  355. print("Warning: Not found %x" % old_start_address, file=sys.stderr)
  356. continue
  357. assert code.start_address == old_start_address, \
  358. "Inexact move address %x for %s" % (old_start_address, code)
  359. self.code_map.Remove(code)
  360. size = code.end_address - code.start_address
  361. code.start_address = new_start_address
  362. code.end_address = new_start_address + size
  363. self.code_map.Add(code)
  364. continue
  365. assert False, "Unknown tag %s" % tag
  366. def Dispose(self):
  367. self.log.close()
  368. self.log_file.close()
  369. @staticmethod
  370. def _DefineStruct(fields):
  371. class Struct(ctypes.Structure):
  372. _fields_ = fields
  373. return Struct
  374. @staticmethod
  375. def _HandleCodeConflict(old_code, new_code):
  376. assert (old_code.start_address == new_code.start_address and
  377. old_code.end_address == new_code.end_address), \
  378. "Conficting code log entries %s and %s" % (old_code, new_code)
  379. if old_code.name == new_code.name:
  380. return
  381. # Code object may be shared by a few functions. Collect the full
  382. # set of names.
  383. old_code.AddName(new_code.name)
  384. class Descriptor(object):
  385. """Descriptor of a structure in the binary trace log."""
  386. CTYPE_MAP = {
  387. "u16": ctypes.c_uint16,
  388. "u32": ctypes.c_uint32,
  389. "u64": ctypes.c_uint64
  390. }
  391. def __init__(self, fields):
  392. class TraceItem(ctypes.Structure):
  393. _fields_ = Descriptor.CtypesFields(fields)
  394. def __str__(self):
  395. return ", ".join("%s: %s" % (field, self.__getattribute__(field))
  396. for field, _ in TraceItem._fields_)
  397. self.ctype = TraceItem
  398. def Read(self, trace, offset):
  399. return self.ctype.from_buffer(trace, offset)
  400. @staticmethod
  401. def CtypesFields(fields):
  402. return [(field, Descriptor.CTYPE_MAP[format]) for (field, format) in fields]
  403. # Please see http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=tree;f=tools/perf
  404. # for the gory details.
  405. # Reference: struct perf_file_header in kernel/tools/perf/util/header.h
  406. TRACE_HEADER_DESC = Descriptor([
  407. ("magic", "u64"),
  408. ("size", "u64"),
  409. ("attr_size", "u64"),
  410. ("attrs_offset", "u64"),
  411. ("attrs_size", "u64"),
  412. ("data_offset", "u64"),
  413. ("data_size", "u64"),
  414. ("event_types_offset", "u64"),
  415. ("event_types_size", "u64")
  416. ])
  417. # Reference: /usr/include/linux/perf_event.h
  418. PERF_EVENT_ATTR_DESC = Descriptor([
  419. ("type", "u32"),
  420. ("size", "u32"),
  421. ("config", "u64"),
  422. ("sample_period_or_freq", "u64"),
  423. ("sample_type", "u64"),
  424. ("read_format", "u64"),
  425. ("flags", "u64"),
  426. ("wakeup_events_or_watermark", "u32"),
  427. ("bp_type", "u32"),
  428. ("bp_addr", "u64"),
  429. ("bp_len", "u64")
  430. ])
  431. # Reference: /usr/include/linux/perf_event.h
  432. PERF_EVENT_HEADER_DESC = Descriptor([
  433. ("type", "u32"),
  434. ("misc", "u16"),
  435. ("size", "u16")
  436. ])
  437. # Reference: kernel/tools/perf/util/event.h
  438. PERF_MMAP_EVENT_BODY_DESC = Descriptor([
  439. ("pid", "u32"),
  440. ("tid", "u32"),
  441. ("addr", "u64"),
  442. ("len", "u64"),
  443. ("pgoff", "u64")
  444. ])
  445. # Reference: kernel/tools/perf/util/event.h
  446. PERF_MMAP2_EVENT_BODY_DESC = Descriptor([
  447. ("pid", "u32"),
  448. ("tid", "u32"),
  449. ("addr", "u64"),
  450. ("len", "u64"),
  451. ("pgoff", "u64"),
  452. ("maj", "u32"),
  453. ("min", "u32"),
  454. ("ino", "u64"),
  455. ("ino_generation", "u64"),
  456. ("prot", "u32"),
  457. ("flags","u32")
  458. ])
  459. # perf_event_attr.sample_type bits control the set of
  460. # perf_sample_event fields.
  461. PERF_SAMPLE_IP = 1 << 0
  462. PERF_SAMPLE_TID = 1 << 1
  463. PERF_SAMPLE_TIME = 1 << 2
  464. PERF_SAMPLE_ADDR = 1 << 3
  465. PERF_SAMPLE_READ = 1 << 4
  466. PERF_SAMPLE_CALLCHAIN = 1 << 5
  467. PERF_SAMPLE_ID = 1 << 6
  468. PERF_SAMPLE_CPU = 1 << 7
  469. PERF_SAMPLE_PERIOD = 1 << 8
  470. PERF_SAMPLE_STREAM_ID = 1 << 9
  471. PERF_SAMPLE_RAW = 1 << 10
  472. # Reference: /usr/include/perf_event.h, the comment for PERF_RECORD_SAMPLE.
  473. PERF_SAMPLE_EVENT_BODY_FIELDS = [
  474. ("ip", "u64", PERF_SAMPLE_IP),
  475. ("pid", "u32", PERF_SAMPLE_TID),
  476. ("tid", "u32", PERF_SAMPLE_TID),
  477. ("time", "u64", PERF_SAMPLE_TIME),
  478. ("addr", "u64", PERF_SAMPLE_ADDR),
  479. ("id", "u64", PERF_SAMPLE_ID),
  480. ("stream_id", "u64", PERF_SAMPLE_STREAM_ID),
  481. ("cpu", "u32", PERF_SAMPLE_CPU),
  482. ("res", "u32", PERF_SAMPLE_CPU),
  483. ("period", "u64", PERF_SAMPLE_PERIOD),
  484. # Don't want to handle read format that comes after the period and
  485. # before the callchain and has variable size.
  486. ("nr", "u64", PERF_SAMPLE_CALLCHAIN)
  487. # Raw data follows the callchain and is ignored.
  488. ]
  489. PERF_SAMPLE_EVENT_IP_FORMAT = "u64"
  490. PERF_RECORD_MMAP = 1
  491. PERF_RECORD_MMAP2 = 10
  492. PERF_RECORD_SAMPLE = 9
  493. class TraceReader(object):
  494. """Perf (linux-2.6/tools/perf) trace file reader."""
  495. _TRACE_HEADER_MAGIC = 4993446653023372624
  496. def __init__(self, trace_name):
  497. self.trace_file = open(trace_name, "r")
  498. self.trace = mmap.mmap(self.trace_file.fileno(), 0, mmap.MAP_PRIVATE)
  499. self.trace_header = TRACE_HEADER_DESC.Read(self.trace, 0)
  500. if self.trace_header.magic != TraceReader._TRACE_HEADER_MAGIC:
  501. print("Warning: unsupported trace header magic", file=sys.stderr)
  502. self.offset = self.trace_header.data_offset
  503. self.limit = self.trace_header.data_offset + self.trace_header.data_size
  504. assert self.limit <= self.trace.size(), \
  505. "Trace data limit exceeds trace file size"
  506. self.header_size = ctypes.sizeof(PERF_EVENT_HEADER_DESC.ctype)
  507. assert self.trace_header.attrs_size != 0, \
  508. "No perf event attributes found in the trace"
  509. perf_event_attr = PERF_EVENT_ATTR_DESC.Read(self.trace,
  510. self.trace_header.attrs_offset)
  511. self.sample_event_body_desc = self._SampleEventBodyDesc(
  512. perf_event_attr.sample_type)
  513. self.callchain_supported = \
  514. (perf_event_attr.sample_type & PERF_SAMPLE_CALLCHAIN) != 0
  515. if self.callchain_supported:
  516. self.ip_struct = Descriptor.CTYPE_MAP[PERF_SAMPLE_EVENT_IP_FORMAT]
  517. self.ip_size = ctypes.sizeof(self.ip_struct)
  518. def ReadEventHeader(self):
  519. if self.offset >= self.limit:
  520. return None, 0
  521. offset = self.offset
  522. header = PERF_EVENT_HEADER_DESC.Read(self.trace, self.offset)
  523. self.offset += header.size
  524. return header, offset
  525. def ReadMmap(self, header, offset):
  526. mmap_info = PERF_MMAP_EVENT_BODY_DESC.Read(self.trace,
  527. offset + self.header_size)
  528. # Read null-terminated filename.
  529. filename = self.trace[offset + self.header_size + ctypes.sizeof(mmap_info):
  530. offset + header.size]
  531. mmap_info.filename = HOST_ROOT + filename[:filename.find(chr(0))]
  532. return mmap_info
  533. def ReadMmap2(self, header, offset):
  534. mmap_info = PERF_MMAP2_EVENT_BODY_DESC.Read(self.trace,
  535. offset + self.header_size)
  536. # Read null-terminated filename.
  537. filename = self.trace[offset + self.header_size + ctypes.sizeof(mmap_info):
  538. offset + header.size]
  539. mmap_info.filename = HOST_ROOT + filename[:filename.find(chr(0))]
  540. return mmap_info
  541. def ReadSample(self, header, offset):
  542. sample = self.sample_event_body_desc.Read(self.trace,
  543. offset + self.header_size)
  544. if not self.callchain_supported:
  545. return sample
  546. sample.ips = []
  547. offset += self.header_size + ctypes.sizeof(sample)
  548. for _ in range(sample.nr):
  549. sample.ips.append(
  550. self.ip_struct.from_buffer(self.trace, offset).value)
  551. offset += self.ip_size
  552. return sample
  553. def Dispose(self):
  554. self.trace.close()
  555. self.trace_file.close()
  556. def _SampleEventBodyDesc(self, sample_type):
  557. assert (sample_type & PERF_SAMPLE_READ) == 0, \
  558. "Can't hande read format in samples"
  559. fields = [(field, format)
  560. for (field, format, bit) in PERF_SAMPLE_EVENT_BODY_FIELDS
  561. if (bit & sample_type) != 0]
  562. return Descriptor(fields)
  563. OBJDUMP_SECTION_HEADER_RE = re.compile(
  564. r"^\s*\d+\s(\.\S+)\s+[a-f0-9]")
  565. OBJDUMP_SYMBOL_LINE_RE = re.compile(
  566. r"^([a-f0-9]+)\s(.{7})\s(\S+)\s+([a-f0-9]+)\s+(?:\.hidden\s+)?(.*)$")
  567. OBJDUMP_DYNAMIC_SYMBOLS_START_RE = re.compile(
  568. r"^DYNAMIC SYMBOL TABLE")
  569. OBJDUMP_SKIP_RE = re.compile(
  570. r"^.*ld\.so\.cache$")
  571. KERNEL_ALLSYMS_FILE = "/proc/kallsyms"
  572. PERF_KERNEL_ALLSYMS_RE = re.compile(
  573. r".*kallsyms.*")
  574. KERNEL_ALLSYMS_LINE_RE = re.compile(
  575. r"^([a-f0-9]+)\s(?:t|T)\s(\S+)$")
  576. class LibraryRepo(object):
  577. def __init__(self):
  578. self.infos = []
  579. self.names = set()
  580. self.ticks = {}
  581. def HasDynamicSymbols(self, filename):
  582. if filename.endswith(".ko"): return False
  583. process = subprocess.Popen(
  584. "%s -h %s" % (OBJDUMP_BIN, filename),
  585. shell=True, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
  586. pipe = process.stdout
  587. try:
  588. for line in pipe:
  589. match = OBJDUMP_SECTION_HEADER_RE.match(line)
  590. if match and match.group(1) == 'dynsym': return True
  591. finally:
  592. pipe.close()
  593. assert process.wait() == 0, "Failed to objdump -h %s" % filename
  594. return False
  595. def Load(self, mmap_info, code_map, options):
  596. # Skip kernel mmaps when requested using the fact that their tid
  597. # is 0.
  598. if mmap_info.tid == 0 and not options.kernel:
  599. return True
  600. if OBJDUMP_SKIP_RE.match(mmap_info.filename):
  601. return True
  602. if PERF_KERNEL_ALLSYMS_RE.match(mmap_info.filename):
  603. return self._LoadKernelSymbols(code_map)
  604. self.infos.append(mmap_info)
  605. mmap_info.ticks = 0
  606. mmap_info.unique_name = self._UniqueMmapName(mmap_info)
  607. if not os.path.exists(mmap_info.filename):
  608. return True
  609. # Request section headers (-h), symbols (-t), and dynamic symbols
  610. # (-T) from objdump.
  611. # Unfortunately, section headers span two lines, so we have to
  612. # keep the just seen section name (from the first line in each
  613. # section header) in the after_section variable.
  614. if self.HasDynamicSymbols(mmap_info.filename):
  615. dynamic_symbols = "-T"
  616. else:
  617. dynamic_symbols = ""
  618. process = subprocess.Popen(
  619. "%s -h -t %s -C %s" % (OBJDUMP_BIN, dynamic_symbols, mmap_info.filename),
  620. shell=True, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
  621. pipe = process.stdout
  622. after_section = None
  623. code_sections = set()
  624. reloc_sections = set()
  625. dynamic = False
  626. try:
  627. for line in pipe:
  628. if after_section:
  629. if line.find("CODE") != -1:
  630. code_sections.add(after_section)
  631. if line.find("RELOC") != -1:
  632. reloc_sections.add(after_section)
  633. after_section = None
  634. continue
  635. match = OBJDUMP_SECTION_HEADER_RE.match(line)
  636. if match:
  637. after_section = match.group(1)
  638. continue
  639. if OBJDUMP_DYNAMIC_SYMBOLS_START_RE.match(line):
  640. dynamic = True
  641. continue
  642. match = OBJDUMP_SYMBOL_LINE_RE.match(line)
  643. if match:
  644. start_address = int(match.group(1), 16)
  645. origin_offset = start_address
  646. flags = match.group(2)
  647. section = match.group(3)
  648. if section in code_sections:
  649. if dynamic or section in reloc_sections:
  650. start_address += mmap_info.addr
  651. size = int(match.group(4), 16)
  652. name = match.group(5)
  653. origin = mmap_info.filename
  654. code_map.Add(Code(name, start_address, start_address + size,
  655. origin, origin_offset))
  656. finally:
  657. pipe.close()
  658. assert process.wait() == 0, "Failed to objdump %s" % mmap_info.filename
  659. def Tick(self, pc):
  660. for i, mmap_info in enumerate(self.infos):
  661. if mmap_info.addr <= pc < (mmap_info.addr + mmap_info.len):
  662. mmap_info.ticks += 1
  663. self.infos[0], self.infos[i] = mmap_info, self.infos[0]
  664. return True
  665. return False
  666. def _UniqueMmapName(self, mmap_info):
  667. name = mmap_info.filename
  668. index = 1
  669. while name in self.names:
  670. name = "%s-%d" % (mmap_info.filename, index)
  671. index += 1
  672. self.names.add(name)
  673. return name
  674. def _LoadKernelSymbols(self, code_map):
  675. if not os.path.exists(KERNEL_ALLSYMS_FILE):
  676. print("Warning: %s not found" % KERNEL_ALLSYMS_FILE, file=sys.stderr)
  677. return False
  678. kallsyms = open(KERNEL_ALLSYMS_FILE, "r")
  679. code = None
  680. for line in kallsyms:
  681. match = KERNEL_ALLSYMS_LINE_RE.match(line)
  682. if match:
  683. start_address = int(match.group(1), 16)
  684. end_address = start_address
  685. name = match.group(2)
  686. if code:
  687. code.end_address = start_address
  688. code_map.Add(code, 16)
  689. code = Code(name, start_address, end_address, "kernel", 0)
  690. return True
  691. def PrintReport(code_map, library_repo, arch, ticks, options):
  692. print("Ticks per symbol:")
  693. used_code = [code for code in code_map.UsedCode()]
  694. used_code.sort(key=lambda x: x.self_ticks, reverse=True)
  695. for i, code in enumerate(used_code):
  696. code_ticks = code.self_ticks
  697. print("%10d %5.1f%% %s [%s]" % (code_ticks, 100. * code_ticks / ticks,
  698. code.FullName(), code.origin))
  699. if options.disasm_all or i < options.disasm_top:
  700. code.PrintAnnotated(arch, options)
  701. print()
  702. print("Ticks per library:")
  703. mmap_infos = [m for m in library_repo.infos if m.ticks > 0]
  704. mmap_infos.sort(key=lambda m: m.ticks, reverse=True)
  705. for mmap_info in mmap_infos:
  706. mmap_ticks = mmap_info.ticks
  707. print("%10d %5.1f%% %s" % (mmap_ticks, 100. * mmap_ticks / ticks,
  708. mmap_info.unique_name))
  709. def PrintDot(code_map, options):
  710. print("digraph G {")
  711. for code in code_map.UsedCode():
  712. if code.self_ticks < 10:
  713. continue
  714. print("n%d [shape=box,label=\"%s\"];" % (code.id, code.name))
  715. if code.callee_ticks:
  716. for callee, ticks in code.callee_ticks.iteritems():
  717. print("n%d -> n%d [label=\"%d\"];" % (code.id, callee.id, ticks))
  718. print("}")
  719. if __name__ == "__main__":
  720. parser = optparse.OptionParser(USAGE)
  721. parser.add_option("--log",
  722. default="v8.log",
  723. help="V8 log file name [default: %default]")
  724. parser.add_option("--trace",
  725. default="perf.data",
  726. help="perf trace file name [default: %default]")
  727. parser.add_option("--kernel",
  728. default=False,
  729. action="store_true",
  730. help="process kernel entries [default: %default]")
  731. parser.add_option("--disasm-top",
  732. default=0,
  733. type="int",
  734. help=("number of top symbols to disassemble and annotate "
  735. "[default: %default]"))
  736. parser.add_option("--disasm-all",
  737. default=False,
  738. action="store_true",
  739. help=("disassemble and annotate all used symbols "
  740. "[default: %default]"))
  741. parser.add_option("--dot",
  742. default=False,
  743. action="store_true",
  744. help="produce dot output (WIP) [default: %default]")
  745. parser.add_option("--quiet", "-q",
  746. default=False,
  747. action="store_true",
  748. help="no auxiliary messages [default: %default]")
  749. parser.add_option("--gc-fake-mmap",
  750. default="/tmp/__v8_gc__",
  751. help="gc fake mmap file [default: %default]")
  752. parser.add_option("--objdump",
  753. default="/usr/bin/objdump",
  754. help="objdump tool to use [default: %default]")
  755. parser.add_option("--host-root",
  756. default="",
  757. help="Path to the host root [default: %default]")
  758. options, args = parser.parse_args()
  759. if not options.quiet:
  760. print("V8 log: %s, %s.ll" % (options.log, options.log))
  761. print("Perf trace file: %s" % options.trace)
  762. V8_GC_FAKE_MMAP = options.gc_fake_mmap
  763. HOST_ROOT = options.host_root
  764. if os.path.exists(options.objdump):
  765. disasm.OBJDUMP_BIN = options.objdump
  766. OBJDUMP_BIN = options.objdump
  767. else:
  768. print("Cannot find %s, falling back to default objdump" % options.objdump)
  769. # Stats.
  770. events = 0
  771. ticks = 0
  772. missed_ticks = 0
  773. really_missed_ticks = 0
  774. optimized_ticks = 0
  775. generated_ticks = 0
  776. v8_internal_ticks = 0
  777. mmap_time = 0
  778. sample_time = 0
  779. # Initialize the log reader.
  780. code_map = CodeMap()
  781. log_reader = LogReader(log_name=options.log + ".ll",
  782. code_map=code_map)
  783. if not options.quiet:
  784. print("Generated code architecture: %s" % log_reader.arch)
  785. print()
  786. sys.stdout.flush()
  787. # Process the code and trace logs.
  788. library_repo = LibraryRepo()
  789. log_reader.ReadUpToGC()
  790. trace_reader = TraceReader(options.trace)
  791. while True:
  792. header, offset = trace_reader.ReadEventHeader()
  793. if not header:
  794. break
  795. events += 1
  796. if header.type == PERF_RECORD_MMAP:
  797. start = time.time()
  798. mmap_info = trace_reader.ReadMmap(header, offset)
  799. if mmap_info.filename == HOST_ROOT + V8_GC_FAKE_MMAP:
  800. log_reader.ReadUpToGC()
  801. else:
  802. library_repo.Load(mmap_info, code_map, options)
  803. mmap_time += time.time() - start
  804. elif header.type == PERF_RECORD_MMAP2:
  805. start = time.time()
  806. mmap_info = trace_reader.ReadMmap2(header, offset)
  807. if mmap_info.filename == HOST_ROOT + V8_GC_FAKE_MMAP:
  808. log_reader.ReadUpToGC()
  809. else:
  810. library_repo.Load(mmap_info, code_map, options)
  811. mmap_time += time.time() - start
  812. elif header.type == PERF_RECORD_SAMPLE:
  813. ticks += 1
  814. start = time.time()
  815. sample = trace_reader.ReadSample(header, offset)
  816. code = code_map.Find(sample.ip)
  817. if code:
  818. code.Tick(sample.ip)
  819. if code.codetype == Code.OPTIMIZED:
  820. optimized_ticks += 1
  821. elif code.codetype == Code.FULL_CODEGEN:
  822. generated_ticks += 1
  823. elif code.codetype == Code.V8INTERNAL:
  824. v8_internal_ticks += 1
  825. else:
  826. missed_ticks += 1
  827. if not library_repo.Tick(sample.ip) and not code:
  828. really_missed_ticks += 1
  829. if trace_reader.callchain_supported:
  830. for ip in sample.ips:
  831. caller_code = code_map.Find(ip)
  832. if caller_code:
  833. if code:
  834. caller_code.CalleeTick(code)
  835. code = caller_code
  836. sample_time += time.time() - start
  837. if options.dot:
  838. PrintDot(code_map, options)
  839. else:
  840. PrintReport(code_map, library_repo, log_reader.arch, ticks, options)
  841. if not options.quiet:
  842. def PrintTicks(number, total, description):
  843. print("%10d %5.1f%% ticks in %s" %
  844. (number, 100.0*number/total, description))
  845. print()
  846. print("Stats:")
  847. print("%10d total trace events" % events)
  848. print("%10d total ticks" % ticks)
  849. print("%10d ticks not in symbols" % missed_ticks)
  850. unaccounted = "unaccounted ticks"
  851. if really_missed_ticks > 0:
  852. unaccounted += " (probably in the kernel, try --kernel)"
  853. PrintTicks(really_missed_ticks, ticks, unaccounted)
  854. PrintTicks(optimized_ticks, ticks, "ticks in optimized code")
  855. PrintTicks(generated_ticks, ticks, "ticks in other lazily compiled code")
  856. PrintTicks(v8_internal_ticks, ticks, "ticks in v8::internal::*")
  857. print("%10d total symbols" % len([c for c in code_map.AllCode()]))
  858. print("%10d used symbols" % len([c for c in code_map.UsedCode()]))
  859. print("%9.2fs library processing time" % mmap_time)
  860. print("%9.2fs tick processing time" % sample_time)
  861. log_reader.Dispose()
  862. trace_reader.Dispose()