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 <cheyuw@google.com>
Reviewed-on: https://chromium-review.googlesource.com/628000
Reviewed-by: Nicolas Boichat <drinkcat@chromium.org>

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<path>[^:]+):(?P<linenum>\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<name>[{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<name>[{}]+)(\[(?P<path>.+)\])?$'.format(C_FUNCTION_NAME))
-    # Example: driver/accel_kionix.c:321 and ??:0
-    addrtoline_regex = re.compile(
-        r'^(?P<path>[^:]+):\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 <wook_task>:\n'
         '	...\n'
         '00001000 <hook_task>:\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 <console_task>:\n'
         '   2000:	b508\t\tpush	{r3, lr}\n'
         '   2002:	f00e fcc5\tbl	1000 <hook_task>\n'
         '   2006:	f00e bd3b\tb.w	53968 <get_program_memory_addr>\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,