From eeeee803b731d292c81c3ec013641181bff4f4bd Mon Sep 17 00:00:00 2001 From: Che-yu Wu Date: Thu, 17 Aug 2017 09:25:11 +0800 Subject: extra/stack_analyzer: Show callsite information. Show callsite details in the call trace. Handle another addr2line failure output. BUG=chromium:648840 BRANCH=none TEST=extra/stack_analyzer/stack_analyzer_unittest.py make BOARD=elm && extra/stack_analyzer/stack_analyzer.py \ --objdump=arm-none-eabi-objdump \ --addr2line=arm-none-eabi-addr2line \ --export_taskinfo=./build/elm/util/export_taskinfo.so \ --section=RW \ --annotation=./extra/stack_analyzer/example_annotation.yaml \ ./build/elm/RW/ec.RW.elf make BOARD=elm SECTION=RW \ ANNOTATION=./extra/stack_analyzer/example_annotation.yaml \ analyzestack Change-Id: I3f36584af85f578f1d298bcd06622ba8e7e5262d Signed-off-by: Che-yu Wu Reviewed-on: https://chromium-review.googlesource.com/628000 Reviewed-by: Nicolas Boichat --- extra/stack_analyzer/README.md | 31 ++++++ extra/stack_analyzer/stack_analyzer.py | 120 ++++++++++++++++++------ extra/stack_analyzer/stack_analyzer_unittest.py | 63 ++++++++----- 3 files changed, 164 insertions(+), 50 deletions(-) diff --git a/extra/stack_analyzer/README.md b/extra/stack_analyzer/README.md index e1be72ebbe..9bb37656f3 100644 --- a/extra/stack_analyzer/README.md +++ b/extra/stack_analyzer/README.md @@ -16,3 +16,34 @@ make BOARD=${BOARD} SECTION=${SECTION} ANNOTATION=${ANNOTATION} analyzestack ``` The `${SECTION}` can be `RO` or `RW`. The `${ANNOTATION}` is a optional annotation file, see the example_annotation.yaml. + +Output +------ + +For each task, it will output the result like below, +``` +Task: PD_C1, Max size: 1156 (932 + 224), Allocated size: 640 +Call Trace: + pd_task (160) [common/usb_pd_protocol.c:1644] 1008a6e8 + -> pd_task [common/usb_pd_protocol.c:1808] 1008ac8a + - handle_request [common/usb_pd_protocol.c:1191] + - handle_data_request [common/usb_pd_protocol.c:798] + -> pd_task [common/usb_pd_protocol.c:2672] 1008c222 + -> [annotation] + pd_send_request_msg.lto_priv.263 (56) [common/usb_pd_protocol.c:653] 1009a0b4 + -> pd_send_request_msg.lto_priv.263 [common/usb_pd_protocol.c:712] 1009a22e0 +``` +The `pd_task` uses 160 bytes on the stack and calls `pd_send_request_msg.lto_priv.263`. + +The callsites to the next function will be shown like below, +``` +-> pd_task [common/usb_pd_protocol.c:1808] 1008ac8a + - handle_request [common/usb_pd_protocol.c:1191] + - handle_data_request [common/usb_pd_protocol.c:798] +-> pd_task [common/usb_pd_protocol.c:2672] 1008c222 +``` +This means one callsite to the next function is at `usb_pd_protocol.c:798`, +but it is inlined to the current function and you can follow the trace: +`usb_pd_protocol.c:1808 -> usb_pd_protocol.c:1191 -> usb_pd_protocol.c:798` to +find the callsite. The second callsite is at `usb_pd_protocol.c:2672`. And the +third one is added by annotation. diff --git a/extra/stack_analyzer/stack_analyzer.py b/extra/stack_analyzer/stack_analyzer.py index 8593821221..4b10bbfe2d 100755 --- a/extra/stack_analyzer/stack_analyzer.py +++ b/extra/stack_analyzer/stack_analyzer.py @@ -355,6 +355,10 @@ class StackAnalyzer(object): Analyze: Run the stack analysis. """ + # Example: "driver/accel_kionix.c:321 (discriminator 3)" + ADDRTOLINE_RE = re.compile( + r'^(?P[^:]+):(?P\d+)(\s+\(discriminator\s+\d+\))?$') + # Errors of annotation resolving. ANNOTATION_ERROR_INVALID = 'invalid signature' ANNOTATION_ERROR_NOTFOUND = 'function is not found' @@ -375,34 +379,60 @@ class StackAnalyzer(object): self.annotation = annotation self.address_to_line_cache = {} - def AddressToLine(self, address): + def AddressToLine(self, address, resolve_inline=False): """Convert address to line. Args: address: Target address. + resolve_inline: Output the stack of inlining. Returns: - line: The corresponding line. + lines: List of the corresponding lines. Raises: StackAnalyzerError: If addr2line is failed. """ - if address in self.address_to_line_cache: - return self.address_to_line_cache[address] + cache_key = (address, resolve_inline) + if cache_key in self.address_to_line_cache: + return self.address_to_line_cache[cache_key] try: - line_text = subprocess.check_output([self.options.addr2line, - '-e', - self.options.elf_path, - '{:x}'.format(address)]) + args = [self.options.addr2line, + '-f', + '-e', + self.options.elf_path, + '{:x}'.format(address)] + if resolve_inline: + args.append('-i') + + line_text = subprocess.check_output(args) except subprocess.CalledProcessError: raise StackAnalyzerError('addr2line failed to resolve lines.') except OSError: raise StackAnalyzerError('Failed to run addr2line.') - line_text = line_text.strip() - self.address_to_line_cache[address] = line_text - return line_text + lines = [line.strip() for line in line_text.splitlines()] + # Assume the output has at least one pair like "function\nlocation\n", and + # they always show up in pairs. + # Example: "handle_request\n + # common/usb_pd_protocol.c:1191\n" + assert len(lines) >= 2 and len(lines) % 2 == 0 + + line_infos = [] + for index in range(0, len(lines), 2): + (function_name, line_text) = lines[index:index + 2] + if line_text in ['??:0', ':?']: + line_infos.append(None) + else: + result = self.ADDRTOLINE_RE.match(line_text) + # Assume the output is always well-formed. + assert result is not None + line_infos.append((function_name.strip(), + result.group('path').strip(), + int(result.group('linenum')))) + + self.address_to_line_cache[cache_key] = line_infos + return line_infos def AnalyzeDisassembly(self, disasm_text): """Parse the disassembly text, analyze, and build a map of all functions. @@ -579,18 +609,14 @@ class StackAnalyzer(object): Map of signatures to functions, set of signatures which can't be resolved. """ C_FUNCTION_NAME = r'_A-Za-z0-9' - ADDRTOLINE_FAILED_SYMBOL = '??' # To eliminate the suffix appended by compilers, try to extract the # C function name from the prefix of symbol name. - # Example: SHA256_transform.constprop.28 + # Example: "SHA256_transform.constprop.28" prefix_name_regex = re.compile( r'^(?P[{0}]+)([^{0}].*)?$'.format(C_FUNCTION_NAME)) - # Example: get_range[driver/accel_kionix.c] + # Example: "get_range[driver/accel_kionix.c]" annotation_signature_regex = re.compile( r'^(?P[{}]+)(\[(?P.+)\])?$'.format(C_FUNCTION_NAME)) - # Example: driver/accel_kionix.c:321 and ??:0 - addrtoline_regex = re.compile( - r'^(?P[^:]+):\d+(\s+\(discriminator\s+\d+\))?$') # Build the symbol map indexed by symbol name. If there are multiple symbols # with the same name, add them into a set. (e.g. symbols of static function @@ -631,13 +657,12 @@ class StackAnalyzer(object): # resolve needed symbol paths. group_map = collections.defaultdict(list) for function in functions: - result = addrtoline_regex.match(self.AddressToLine(function.address)) - # Assume the output of addr2line is always well-formed. - assert result is not None - symbol_path = result.group('path').strip() - if symbol_path == ADDRTOLINE_FAILED_SYMBOL: + line_info = self.AddressToLine(function.address)[0] + if line_info is None: continue + (_, symbol_path, _) = line_info + # Group the functions with the same symbol signature (symbol name + # symbol path). Assume they are the same copies and do the same # annotation operations of them because we don't know which copy is @@ -849,6 +874,26 @@ class StackAnalyzer(object): Raises: StackAnalyzerError: If disassembly fails. """ + def PrintInlineStack(address, prefix=''): + """Print beautiful inline stack. + + Args: + address: Address. + prefix: Prefix of each line. + """ + line_texts = [] + for line_info in reversed(self.AddressToLine(address, True)): + if line_info is None: + (function_name, path, linenum) = ('??', '??', 0) + else: + (function_name, path, linenum) = line_info + + line_texts.append('{} [{}:{}]'.format(function_name, path, linenum)) + + print('{}-> {} {:x}'.format(prefix, line_texts[0], address)) + for depth, line_text in enumerate(line_texts[1:]): + print('{} {}- {}'.format(prefix, ' ' * depth, line_text)) + # Analyze disassembly. try: disasm_text = subprocess.check_output([self.options.objdump, @@ -877,22 +922,39 @@ class StackAnalyzer(object): print('Call Trace:') curr_func = routine_func while curr_func is not None: - line = self.AddressToLine(curr_func.address) - output = '\t{} ({}) {:x} [{}]'.format(curr_func.name, - curr_func.stack_frame, - curr_func.address, - line) + line_info = self.AddressToLine(curr_func.address)[0] + if line_info is None: + (path, linenum) = ('??', 0) + else: + (_, path, linenum) = line_info + + output = ' {} ({}) [{}:{}] {:x}'.format(curr_func.name, + curr_func.stack_frame, + path, + linenum, + curr_func.address) if len(cycle_groups[curr_func.cycle_index]) > 0: # If its cycle group isn't empty, it is in a cycle. output += ' [cycle]' print(output) - curr_func = curr_func.stack_successor + + succ_func = curr_func.stack_successor + if succ_func is not None: + for callsite in curr_func.callsites: + if callsite.callee is succ_func: + indent_prefix = ' ' + if callsite.address is None: + print('{}-> [annotation]'.format(indent_prefix)) + else: + PrintInlineStack(callsite.address, indent_prefix) + + curr_func = succ_func if len(failed_sigs) > 0: print('Failed to resolve some annotation signatures:') for sig, error in failed_sigs: - print('\t{}: {}'.format(sig, error)) + print(' {}: {}'.format(sig, error)) def ParseArgs(): diff --git a/extra/stack_analyzer/stack_analyzer_unittest.py b/extra/stack_analyzer/stack_analyzer_unittest.py index e011a670c4..03144fda32 100755 --- a/extra/stack_analyzer/stack_analyzer_unittest.py +++ b/extra/stack_analyzer/stack_analyzer_unittest.py @@ -219,13 +219,13 @@ class StackAnalyzerTest(unittest.TestCase): } # Set address_to_line_cache to fake the results of addr2line. self.analyzer.address_to_line_cache = { - 0x1000: 'a.c:10', - 0x2000: 'b.c:20', - 0x4000: './a.c:30', - 0x5000: 'b.c:40', - 0x12000: 't.c:10', - 0x13000: 'x.c:12', - 0x13100: 'x.c:12', + (0x1000, False): [('hook_task', 'a.c', 10)], + (0x2000, False): [('console_task', 'b.c', 20)], + (0x4000, False): [('toudhpad_calc', './a.c', 20)], + (0x5000, False): [('touchpad_calc.constprop.42', 'b.c', 40)], + (0x12000, False): [('trackpad_range', 't.c', 10)], + (0x13000, False): [('inlined_mul', 'x.c', 12)], + (0x13100, False): [('inlined_mul', 'x.c', 12)], } self.analyzer.annotation = { 'add': { @@ -404,15 +404,33 @@ class StackAnalyzerTest(unittest.TestCase): @mock.patch('subprocess.check_output') def testAddressToLine(self, checkoutput_mock): - checkoutput_mock.return_value = 'test.c:1' - self.assertEqual(self.analyzer.AddressToLine(0x1234), 'test.c:1') + checkoutput_mock.return_value = 'fake_func\ntest.c:1' + self.assertEqual(self.analyzer.AddressToLine(0x1234), + [('fake_func', 'test.c', 1)]) checkoutput_mock.assert_called_once_with( - ['addr2line', '-e', './ec.RW.elf', '1234']) + ['addr2line', '-f', '-e', './ec.RW.elf', '1234']) + checkoutput_mock.reset_mock() - checkoutput_mock.return_value = 'test.c:1 (discriminator 1289031)' - self.assertEqual(self.analyzer.AddressToLine(0x1234), 'test.c:1') + checkoutput_mock.return_value = 'fake_func\na.c:1\nbake_func\nb.c:2\n' + self.assertEqual(self.analyzer.AddressToLine(0x1234, True), + [('fake_func', 'a.c', 1), ('bake_func', 'b.c', 2)]) checkoutput_mock.assert_called_once_with( - ['addr2line', '-e', './ec.RW.elf', '1234']) + ['addr2line', '-f', '-e', './ec.RW.elf', '1234', '-i']) + checkoutput_mock.reset_mock() + + checkoutput_mock.return_value = 'fake_func\ntest.c:1 (discriminator 128)' + self.assertEqual(self.analyzer.AddressToLine(0x12345), + [('fake_func', 'test.c', 1)]) + checkoutput_mock.assert_called_once_with( + ['addr2line', '-f', '-e', './ec.RW.elf', '12345']) + checkoutput_mock.reset_mock() + + checkoutput_mock.return_value = '??\n:?\nbake_func\nb.c:2\n' + self.assertEqual(self.analyzer.AddressToLine(0x123456), + [None, ('bake_func', 'b.c', 2)]) + checkoutput_mock.assert_called_once_with( + ['addr2line', '-f', '-e', './ec.RW.elf', '123456']) + checkoutput_mock.reset_mock() with self.assertRaisesRegexp(sa.StackAnalyzerError, 'addr2line failed to resolve lines.'): @@ -434,15 +452,16 @@ class StackAnalyzerTest(unittest.TestCase): '00000900 :\n' ' ...\n' '00001000 :\n' - ' 1000: 4770\t\tbx lr\n' - ' 1004: 00015cfc\t.word 0x00015cfc\n' + ' 1000: b508\t\tpush {r3, lr}\n' + ' 1002: 4770\t\tbx lr\n' + ' 1006: 00015cfc\t.word 0x00015cfc\n' '00002000 :\n' ' 2000: b508\t\tpush {r3, lr}\n' ' 2002: f00e fcc5\tbl 1000 \n' ' 2006: f00e bd3b\tb.w 53968 \n' ) - addrtoline_mock.return_value = '??:0' + addrtoline_mock.return_value = [('??', '??', 0)] self.analyzer.annotation = {'remove': ['fake_func']} with mock.patch('__builtin__.print') as print_mock: @@ -450,15 +469,17 @@ class StackAnalyzerTest(unittest.TestCase): self.analyzer.Analyze() print_mock.assert_has_calls([ mock.call( - 'Task: HOOKS, Max size: 224 (0 + 224), Allocated size: 2048'), + 'Task: HOOKS, Max size: 232 (8 + 224), Allocated size: 2048'), mock.call('Call Trace:'), - mock.call('\thook_task (0) 1000 [??:0]'), + mock.call(' hook_task (8) [??:0] 1000'), mock.call( - 'Task: CONSOLE, Max size: 232 (8 + 224), Allocated size: 460'), + 'Task: CONSOLE, Max size: 240 (16 + 224), Allocated size: 460'), mock.call('Call Trace:'), - mock.call('\tconsole_task (8) 2000 [??:0]'), + mock.call(' console_task (8) [??:0] 2000'), + mock.call(' -> ?? [??:0] 2002'), + mock.call(' hook_task (8) [??:0] 1000'), mock.call('Failed to resolve some annotation signatures:'), - mock.call('\tfake_func: function is not found'), + mock.call(' fake_func: function is not found'), ]) with self.assertRaisesRegexp(sa.StackAnalyzerError, -- cgit v1.2.1