| OLD | NEW |
| 1 #!/usr/bin/env python | 1 #!/usr/bin/env python |
| 2 # | 2 # |
| 3 # Copyright 2012 the V8 project authors. All rights reserved. | 3 # Copyright 2012 the V8 project authors. All rights reserved. |
| 4 # Redistribution and use in source and binary forms, with or without | 4 # Redistribution and use in source and binary forms, with or without |
| 5 # modification, are permitted provided that the following conditions are | 5 # modification, are permitted provided that the following conditions are |
| 6 # met: | 6 # met: |
| 7 # | 7 # |
| 8 # * Redistributions of source code must retain the above copyright | 8 # * Redistributions of source code must retain the above copyright |
| 9 # notice, this list of conditions and the following disclaimer. | 9 # notice, this list of conditions and the following disclaimer. |
| 10 # * Redistributions in binary form must reproduce the above | 10 # * Redistributions in binary form must reproduce the above |
| (...skipping 48 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 59 default. That's not enough for "-c 10000". Set it to some higher value: | 59 default. That's not enough for "-c 10000". Set it to some higher value: |
| 60 $ echo 10000000 | sudo tee /proc/sys/kernel/perf_event_max_sample_rate | 60 $ echo 10000000 | sudo tee /proc/sys/kernel/perf_event_max_sample_rate |
| 61 You can also make the warning about kernel address maps go away: | 61 You can also make the warning about kernel address maps go away: |
| 62 $ echo 0 | sudo tee /proc/sys/kernel/kptr_restrict | 62 $ echo 0 | sudo tee /proc/sys/kernel/kptr_restrict |
| 63 | 63 |
| 64 We have a convenience script that handles all of the above for you: | 64 We have a convenience script that handles all of the above for you: |
| 65 $ tools/run-llprof.sh ./d8 bench.js | 65 $ tools/run-llprof.sh ./d8 bench.js |
| 66 | 66 |
| 67 Examples: | 67 Examples: |
| 68 # Print flat profile with annotated disassembly for the 10 top | 68 # Print flat profile with annotated disassembly for the 10 top |
| 69 # symbols. Use default log names and include the snapshot log. | 69 # symbols. Use default log names. |
| 70 $ %prog --snapshot --disasm-top=10 | 70 $ %prog --disasm-top=10 |
| 71 | 71 |
| 72 # Print flat profile with annotated disassembly for all used symbols. | 72 # Print flat profile with annotated disassembly for all used symbols. |
| 73 # Use default log names and include kernel symbols into analysis. | 73 # Use default log names and include kernel symbols into analysis. |
| 74 $ %prog --disasm-all --kernel | 74 $ %prog --disasm-all --kernel |
| 75 | 75 |
| 76 # Print flat profile. Use custom log names. | 76 # Print flat profile. Use custom log names. |
| 77 $ %prog --log=foo.log --snapshot-log=snap-foo.log --trace=foo.data --snapshot | 77 $ %prog --log=foo.log --trace=foo.data |
| 78 """ | 78 """ |
| 79 | 79 |
| 80 | 80 |
| 81 JS_ORIGIN = "js" | 81 JS_ORIGIN = "js" |
| 82 JS_SNAPSHOT_ORIGIN = "js-snapshot" | 82 |
| 83 | 83 |
| 84 class Code(object): | 84 class Code(object): |
| 85 """Code object.""" | 85 """Code object.""" |
| 86 | 86 |
| 87 _id = 0 | 87 _id = 0 |
| 88 UNKNOWN = 0 | 88 UNKNOWN = 0 |
| 89 V8INTERNAL = 1 | 89 V8INTERNAL = 1 |
| 90 FULL_CODEGEN = 2 | 90 FULL_CODEGEN = 2 |
| 91 OPTIMIZED = 3 | 91 OPTIMIZED = 3 |
| 92 | 92 |
| (...skipping 99 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 192 | 192 |
| 193 def __str__(self): | 193 def __str__(self): |
| 194 return "%s [0x%x, 0x%x) size: %d origin: %s" % ( | 194 return "%s [0x%x, 0x%x) size: %d origin: %s" % ( |
| 195 self.name, | 195 self.name, |
| 196 self.start_address, | 196 self.start_address, |
| 197 self.end_address, | 197 self.end_address, |
| 198 self.end_address - self.start_address, | 198 self.end_address - self.start_address, |
| 199 self.origin) | 199 self.origin) |
| 200 | 200 |
| 201 def _GetDisasmLines(self, arch, options): | 201 def _GetDisasmLines(self, arch, options): |
| 202 if self.origin == JS_ORIGIN or self.origin == JS_SNAPSHOT_ORIGIN: | 202 inplace = True |
| 203 inplace = False | 203 filename = self.origin |
| 204 filename = options.log + ".ll" | |
| 205 else: | |
| 206 inplace = True | |
| 207 filename = self.origin | |
| 208 return disasm.GetDisasmLines(filename, | 204 return disasm.GetDisasmLines(filename, |
| 209 self.origin_offset, | 205 self.origin_offset, |
| 210 self.end_address - self.start_address, | 206 self.end_address - self.start_address, |
| 211 arch, | 207 arch, |
| 212 inplace) | 208 inplace) |
| 213 | 209 |
| 214 | 210 |
| 215 class CodePage(object): | 211 class CodePage(object): |
| 216 """Group of adjacent code objects.""" | 212 """Group of adjacent code objects.""" |
| 217 | 213 |
| (...skipping 103 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 321 | 317 |
| 322 | 318 |
| 323 class CodeInfo(object): | 319 class CodeInfo(object): |
| 324 """Generic info about generated code objects.""" | 320 """Generic info about generated code objects.""" |
| 325 | 321 |
| 326 def __init__(self, arch, header_size): | 322 def __init__(self, arch, header_size): |
| 327 self.arch = arch | 323 self.arch = arch |
| 328 self.header_size = header_size | 324 self.header_size = header_size |
| 329 | 325 |
| 330 | 326 |
| 331 class SnapshotLogReader(object): | |
| 332 """V8 snapshot log reader.""" | |
| 333 | |
| 334 _SNAPSHOT_CODE_NAME_RE = re.compile( | |
| 335 r"snapshot-code-name,(\d+),\"(.*)\"") | |
| 336 | |
| 337 def __init__(self, log_name): | |
| 338 self.log_name = log_name | |
| 339 | |
| 340 def ReadNameMap(self): | |
| 341 log = open(self.log_name, "r") | |
| 342 try: | |
| 343 snapshot_pos_to_name = {} | |
| 344 for line in log: | |
| 345 match = SnapshotLogReader._SNAPSHOT_CODE_NAME_RE.match(line) | |
| 346 if match: | |
| 347 pos = int(match.group(1)) | |
| 348 name = match.group(2) | |
| 349 snapshot_pos_to_name[pos] = name | |
| 350 finally: | |
| 351 log.close() | |
| 352 return snapshot_pos_to_name | |
| 353 | |
| 354 | |
| 355 class LogReader(object): | 327 class LogReader(object): |
| 356 """V8 low-level (binary) log reader.""" | 328 """V8 low-level (binary) log reader.""" |
| 357 | 329 |
| 358 _ARCH_TO_POINTER_TYPE_MAP = { | 330 _ARCH_TO_POINTER_TYPE_MAP = { |
| 359 "ia32": ctypes.c_uint32, | 331 "ia32": ctypes.c_uint32, |
| 360 "arm": ctypes.c_uint32, | 332 "arm": ctypes.c_uint32, |
| 361 "mips": ctypes.c_uint32, | 333 "mips": ctypes.c_uint32, |
| 362 "x64": ctypes.c_uint64, | 334 "x64": ctypes.c_uint64, |
| 363 "arm64": ctypes.c_uint64 | 335 "arm64": ctypes.c_uint64 |
| 364 } | 336 } |
| 365 | 337 |
| 366 _CODE_CREATE_TAG = "C" | 338 _CODE_CREATE_TAG = "C" |
| 367 _CODE_MOVE_TAG = "M" | 339 _CODE_MOVE_TAG = "M" |
| 368 _SNAPSHOT_POSITION_TAG = "P" | |
| 369 _CODE_MOVING_GC_TAG = "G" | 340 _CODE_MOVING_GC_TAG = "G" |
| 370 | 341 |
| 371 def __init__(self, log_name, code_map, snapshot_pos_to_name): | 342 def __init__(self, log_name, code_map): |
| 372 self.log_file = open(log_name, "r") | 343 self.log_file = open(log_name, "r") |
| 373 self.log = mmap.mmap(self.log_file.fileno(), 0, mmap.MAP_PRIVATE) | 344 self.log = mmap.mmap(self.log_file.fileno(), 0, mmap.MAP_PRIVATE) |
| 374 self.log_pos = 0 | 345 self.log_pos = 0 |
| 375 self.code_map = code_map | 346 self.code_map = code_map |
| 376 self.snapshot_pos_to_name = snapshot_pos_to_name | |
| 377 self.address_to_snapshot_name = {} | |
| 378 | 347 |
| 379 self.arch = self.log[:self.log.find("\0")] | 348 self.arch = self.log[:self.log.find("\0")] |
| 380 self.log_pos += len(self.arch) + 1 | 349 self.log_pos += len(self.arch) + 1 |
| 381 assert self.arch in LogReader._ARCH_TO_POINTER_TYPE_MAP, \ | 350 assert self.arch in LogReader._ARCH_TO_POINTER_TYPE_MAP, \ |
| 382 "Unsupported architecture %s" % self.arch | 351 "Unsupported architecture %s" % self.arch |
| 383 pointer_type = LogReader._ARCH_TO_POINTER_TYPE_MAP[self.arch] | 352 pointer_type = LogReader._ARCH_TO_POINTER_TYPE_MAP[self.arch] |
| 384 | 353 |
| 385 self.code_create_struct = LogReader._DefineStruct([ | 354 self.code_create_struct = LogReader._DefineStruct([ |
| 386 ("name_size", ctypes.c_int32), | 355 ("name_size", ctypes.c_int32), |
| 387 ("code_address", pointer_type), | 356 ("code_address", pointer_type), |
| 388 ("code_size", ctypes.c_int32)]) | 357 ("code_size", ctypes.c_int32)]) |
| 389 | 358 |
| 390 self.code_move_struct = LogReader._DefineStruct([ | 359 self.code_move_struct = LogReader._DefineStruct([ |
| 391 ("from_address", pointer_type), | 360 ("from_address", pointer_type), |
| 392 ("to_address", pointer_type)]) | 361 ("to_address", pointer_type)]) |
| 393 | 362 |
| 394 self.code_delete_struct = LogReader._DefineStruct([ | 363 self.code_delete_struct = LogReader._DefineStruct([ |
| 395 ("address", pointer_type)]) | 364 ("address", pointer_type)]) |
| 396 | 365 |
| 397 self.snapshot_position_struct = LogReader._DefineStruct([ | |
| 398 ("address", pointer_type), | |
| 399 ("position", ctypes.c_int32)]) | |
| 400 | |
| 401 def ReadUpToGC(self): | 366 def ReadUpToGC(self): |
| 402 while self.log_pos < self.log.size(): | 367 while self.log_pos < self.log.size(): |
| 403 tag = self.log[self.log_pos] | 368 tag = self.log[self.log_pos] |
| 404 self.log_pos += 1 | 369 self.log_pos += 1 |
| 405 | 370 |
| 406 if tag == LogReader._CODE_MOVING_GC_TAG: | 371 if tag == LogReader._CODE_MOVING_GC_TAG: |
| 407 self.address_to_snapshot_name.clear() | |
| 408 return | 372 return |
| 409 | 373 |
| 410 if tag == LogReader._CODE_CREATE_TAG: | 374 if tag == LogReader._CODE_CREATE_TAG: |
| 411 event = self.code_create_struct.from_buffer(self.log, self.log_pos) | 375 event = self.code_create_struct.from_buffer(self.log, self.log_pos) |
| 412 self.log_pos += ctypes.sizeof(event) | 376 self.log_pos += ctypes.sizeof(event) |
| 413 start_address = event.code_address | 377 start_address = event.code_address |
| 414 end_address = start_address + event.code_size | 378 end_address = start_address + event.code_size |
| 415 if start_address in self.address_to_snapshot_name: | 379 name = self.log[self.log_pos:self.log_pos + event.name_size] |
| 416 name = self.address_to_snapshot_name[start_address] | 380 origin = JS_ORIGIN |
| 417 origin = JS_SNAPSHOT_ORIGIN | |
| 418 else: | |
| 419 name = self.log[self.log_pos:self.log_pos + event.name_size] | |
| 420 origin = JS_ORIGIN | |
| 421 self.log_pos += event.name_size | 381 self.log_pos += event.name_size |
| 422 origin_offset = self.log_pos | 382 origin_offset = self.log_pos |
| 423 self.log_pos += event.code_size | 383 self.log_pos += event.code_size |
| 424 code = Code(name, start_address, end_address, origin, origin_offset) | 384 code = Code(name, start_address, end_address, origin, origin_offset) |
| 425 conficting_code = self.code_map.Find(start_address) | 385 conficting_code = self.code_map.Find(start_address) |
| 426 if conficting_code: | 386 if conficting_code: |
| 427 if not (conficting_code.start_address == code.start_address and | 387 if not (conficting_code.start_address == code.start_address and |
| 428 conficting_code.end_address == code.end_address): | 388 conficting_code.end_address == code.end_address): |
| 429 self.code_map.Remove(conficting_code) | 389 self.code_map.Remove(conficting_code) |
| 430 else: | 390 else: |
| (...skipping 20 matching lines...) Expand all Loading... |
| 451 continue | 411 continue |
| 452 assert code.start_address == old_start_address, \ | 412 assert code.start_address == old_start_address, \ |
| 453 "Inexact move address %x for %s" % (old_start_address, code) | 413 "Inexact move address %x for %s" % (old_start_address, code) |
| 454 self.code_map.Remove(code) | 414 self.code_map.Remove(code) |
| 455 size = code.end_address - code.start_address | 415 size = code.end_address - code.start_address |
| 456 code.start_address = new_start_address | 416 code.start_address = new_start_address |
| 457 code.end_address = new_start_address + size | 417 code.end_address = new_start_address + size |
| 458 self.code_map.Add(code) | 418 self.code_map.Add(code) |
| 459 continue | 419 continue |
| 460 | 420 |
| 461 if tag == LogReader._SNAPSHOT_POSITION_TAG: | |
| 462 event = self.snapshot_position_struct.from_buffer(self.log, | |
| 463 self.log_pos) | |
| 464 self.log_pos += ctypes.sizeof(event) | |
| 465 start_address = event.address | |
| 466 snapshot_pos = event.position | |
| 467 if snapshot_pos in self.snapshot_pos_to_name: | |
| 468 self.address_to_snapshot_name[start_address] = \ | |
| 469 self.snapshot_pos_to_name[snapshot_pos] | |
| 470 continue | |
| 471 | |
| 472 assert False, "Unknown tag %s" % tag | 421 assert False, "Unknown tag %s" % tag |
| 473 | 422 |
| 474 def Dispose(self): | 423 def Dispose(self): |
| 475 self.log.close() | 424 self.log.close() |
| 476 self.log_file.close() | 425 self.log_file.close() |
| 477 | 426 |
| 478 @staticmethod | 427 @staticmethod |
| 479 def _DefineStruct(fields): | 428 def _DefineStruct(fields): |
| 480 class Struct(ctypes.Structure): | 429 class Struct(ctypes.Structure): |
| 481 _fields_ = fields | 430 _fields_ = fields |
| (...skipping 395 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 877 continue | 826 continue |
| 878 print "n%d [shape=box,label=\"%s\"];" % (code.id, code.name) | 827 print "n%d [shape=box,label=\"%s\"];" % (code.id, code.name) |
| 879 if code.callee_ticks: | 828 if code.callee_ticks: |
| 880 for callee, ticks in code.callee_ticks.iteritems(): | 829 for callee, ticks in code.callee_ticks.iteritems(): |
| 881 print "n%d -> n%d [label=\"%d\"];" % (code.id, callee.id, ticks) | 830 print "n%d -> n%d [label=\"%d\"];" % (code.id, callee.id, ticks) |
| 882 print "}" | 831 print "}" |
| 883 | 832 |
| 884 | 833 |
| 885 if __name__ == "__main__": | 834 if __name__ == "__main__": |
| 886 parser = optparse.OptionParser(USAGE) | 835 parser = optparse.OptionParser(USAGE) |
| 887 parser.add_option("--snapshot-log", | |
| 888 default="obj/release/snapshot.log", | |
| 889 help="V8 snapshot log file name [default: %default]") | |
| 890 parser.add_option("--log", | 836 parser.add_option("--log", |
| 891 default="v8.log", | 837 default="v8.log", |
| 892 help="V8 log file name [default: %default]") | 838 help="V8 log file name [default: %default]") |
| 893 parser.add_option("--snapshot", | |
| 894 default=False, | |
| 895 action="store_true", | |
| 896 help="process V8 snapshot log [default: %default]") | |
| 897 parser.add_option("--trace", | 839 parser.add_option("--trace", |
| 898 default="perf.data", | 840 default="perf.data", |
| 899 help="perf trace file name [default: %default]") | 841 help="perf trace file name [default: %default]") |
| 900 parser.add_option("--kernel", | 842 parser.add_option("--kernel", |
| 901 default=False, | 843 default=False, |
| 902 action="store_true", | 844 action="store_true", |
| 903 help="process kernel entries [default: %default]") | 845 help="process kernel entries [default: %default]") |
| 904 parser.add_option("--disasm-top", | 846 parser.add_option("--disasm-top", |
| 905 default=0, | 847 default=0, |
| 906 type="int", | 848 type="int", |
| (...skipping 17 matching lines...) Expand all Loading... |
| 924 help="gc fake mmap file [default: %default]") | 866 help="gc fake mmap file [default: %default]") |
| 925 parser.add_option("--objdump", | 867 parser.add_option("--objdump", |
| 926 default="/usr/bin/objdump", | 868 default="/usr/bin/objdump", |
| 927 help="objdump tool to use [default: %default]") | 869 help="objdump tool to use [default: %default]") |
| 928 parser.add_option("--host-root", | 870 parser.add_option("--host-root", |
| 929 default="", | 871 default="", |
| 930 help="Path to the host root [default: %default]") | 872 help="Path to the host root [default: %default]") |
| 931 options, args = parser.parse_args() | 873 options, args = parser.parse_args() |
| 932 | 874 |
| 933 if not options.quiet: | 875 if not options.quiet: |
| 934 if options.snapshot: | 876 print "V8 log: %s, %s.ll" % (options.log, options.log) |
| 935 print "V8 logs: %s, %s, %s.ll" % (options.snapshot_log, | |
| 936 options.log, | |
| 937 options.log) | |
| 938 else: | |
| 939 print "V8 log: %s, %s.ll (no snapshot)" % (options.log, options.log) | |
| 940 print "Perf trace file: %s" % options.trace | 877 print "Perf trace file: %s" % options.trace |
| 941 | 878 |
| 942 V8_GC_FAKE_MMAP = options.gc_fake_mmap | 879 V8_GC_FAKE_MMAP = options.gc_fake_mmap |
| 943 HOST_ROOT = options.host_root | 880 HOST_ROOT = options.host_root |
| 944 if os.path.exists(options.objdump): | 881 if os.path.exists(options.objdump): |
| 945 disasm.OBJDUMP_BIN = options.objdump | 882 disasm.OBJDUMP_BIN = options.objdump |
| 946 OBJDUMP_BIN = options.objdump | 883 OBJDUMP_BIN = options.objdump |
| 947 else: | 884 else: |
| 948 print "Cannot find %s, falling back to default objdump" % options.objdump | 885 print "Cannot find %s, falling back to default objdump" % options.objdump |
| 949 | 886 |
| 950 # Stats. | 887 # Stats. |
| 951 events = 0 | 888 events = 0 |
| 952 ticks = 0 | 889 ticks = 0 |
| 953 missed_ticks = 0 | 890 missed_ticks = 0 |
| 954 really_missed_ticks = 0 | 891 really_missed_ticks = 0 |
| 955 optimized_ticks = 0 | 892 optimized_ticks = 0 |
| 956 generated_ticks = 0 | 893 generated_ticks = 0 |
| 957 v8_internal_ticks = 0 | 894 v8_internal_ticks = 0 |
| 958 mmap_time = 0 | 895 mmap_time = 0 |
| 959 sample_time = 0 | 896 sample_time = 0 |
| 960 | 897 |
| 961 # Process the snapshot log to fill the snapshot name map. | |
| 962 snapshot_name_map = {} | |
| 963 if options.snapshot: | |
| 964 snapshot_log_reader = SnapshotLogReader(log_name=options.snapshot_log) | |
| 965 snapshot_name_map = snapshot_log_reader.ReadNameMap() | |
| 966 | |
| 967 # Initialize the log reader. | 898 # Initialize the log reader. |
| 968 code_map = CodeMap() | 899 code_map = CodeMap() |
| 969 log_reader = LogReader(log_name=options.log + ".ll", | 900 log_reader = LogReader(log_name=options.log + ".ll", |
| 970 code_map=code_map, | 901 code_map=code_map) |
| 971 snapshot_pos_to_name=snapshot_name_map) | |
| 972 if not options.quiet: | 902 if not options.quiet: |
| 973 print "Generated code architecture: %s" % log_reader.arch | 903 print "Generated code architecture: %s" % log_reader.arch |
| 974 print | 904 print |
| 975 sys.stdout.flush() | 905 sys.stdout.flush() |
| 976 | 906 |
| 977 # Process the code and trace logs. | 907 # Process the code and trace logs. |
| 978 library_repo = LibraryRepo() | 908 library_repo = LibraryRepo() |
| 979 log_reader.ReadUpToGC() | 909 log_reader.ReadUpToGC() |
| 980 trace_reader = TraceReader(options.trace) | 910 trace_reader = TraceReader(options.trace) |
| 981 while True: | 911 while True: |
| (...skipping 64 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 1046 PrintTicks(optimized_ticks, ticks, "ticks in optimized code") | 976 PrintTicks(optimized_ticks, ticks, "ticks in optimized code") |
| 1047 PrintTicks(generated_ticks, ticks, "ticks in other lazily compiled code") | 977 PrintTicks(generated_ticks, ticks, "ticks in other lazily compiled code") |
| 1048 PrintTicks(v8_internal_ticks, ticks, "ticks in v8::internal::*") | 978 PrintTicks(v8_internal_ticks, ticks, "ticks in v8::internal::*") |
| 1049 print "%10d total symbols" % len([c for c in code_map.AllCode()]) | 979 print "%10d total symbols" % len([c for c in code_map.AllCode()]) |
| 1050 print "%10d used symbols" % len([c for c in code_map.UsedCode()]) | 980 print "%10d used symbols" % len([c for c in code_map.UsedCode()]) |
| 1051 print "%9.2fs library processing time" % mmap_time | 981 print "%9.2fs library processing time" % mmap_time |
| 1052 print "%9.2fs tick processing time" % sample_time | 982 print "%9.2fs tick processing time" % sample_time |
| 1053 | 983 |
| 1054 log_reader.Dispose() | 984 log_reader.Dispose() |
| 1055 trace_reader.Dispose() | 985 trace_reader.Dispose() |
| OLD | NEW |