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 |