Re: [kvm-unit-tests 5/5] scripts: pretty print stack traces

[Andrew Jones <drjones@redhat.com>]

On Tue, Mar 01, 2016 at 10:34:53PM +0100, Paolo Bonzini wrote:
> 
> 
> On 01/03/2016 22:27, Peter Feiner wrote:
> > Optionally pretty print stacks in test.log with 'run_tests.sh -p'.
> > 
> > The script runs addresses through addr2line to get file names and line
> > numbers.  Also prints out source code lines if files are available.
> > For example
> > 
> > 0x004013f5: ac_test_exec at x86/access.c:818
> >             }
> >       >     ac_test_setup_pte(at, pool);
> >             r = ac_test_do_access(at);
> > 0x004014dd: ac_test_run at x86/access.c:852
> >                 ++tests;
> >       >         successes += ac_test_exec(&at, &pool);
> >             } while (ac_test_bump(&at));
> > 0x0040157d: main at x86/access.c:873
> >             printf("starting test\n\n");
> >       >     r = ac_test_run();
> >             return r ? 0 : 1;
> > 0x0040028e: start64 at x86/cstart64.S:206
> >                 lea __argv(%rip), %rsi
> >       >         call main
> >                 mov %eax, %edi
> > 
> > Signed-off-by: Peter Feiner <pfeiner@google.com>
> > ---
> >  run_tests.sh                   | 10 +++++--
> >  scripts/pretty_print_stacks.py | 61 ++++++++++++++++++++++++++++++++++++++++++
> >  2 files changed, 69 insertions(+), 2 deletions(-)
> >  create mode 100755 scripts/pretty_print_stacks.py
> > 
> > diff --git a/run_tests.sh b/run_tests.sh
> > index 2c8af36..13bc089 100755
> > --- a/run_tests.sh
> > +++ b/run_tests.sh
> > @@ -1,6 +1,7 @@
> >  #!/bin/bash
> >  
> >  verbose="no"
> > +pretty="no"
> >  
> >  if [ ! -f config.mak ]; then
> >      echo "run ./configure && make first. See ./configure -h"
> > @@ -18,6 +19,7 @@ Usage: $0 [-g group] [-h] [-v]
> >      -g: Only execute tests in the given group
> >      -h: Output this help text
> >      -v: Enables verbose mode
> > +    -p: Pretty print stack traces in test.log
> >  
> >  Set the environment variable QEMU=/path/to/qemu-system-ARCH to
> >  specify the appropriate qemu binary for ARCH-run.
> > @@ -27,8 +29,9 @@ EOF
> >  
> >  RUNTIME_arch_run="./$TEST_DIR/run"
> >  source scripts/runtime.bash
> > +log_redir=">> test.log"
> >  
> > -while getopts "g:hv" opt; do
> > +while getopts "g:hvp" opt; do
> >      case $opt in
> >          g)
> >              only_group=$OPTARG
> > @@ -40,13 +43,16 @@ while getopts "g:hv" opt; do
> >          v)
> >              verbose="yes"
> >              ;;
> > +        p)
> > +           log_redir="> >(./scripts/pretty_print_stacks.py \$kernel >> test.log)"
> > +           ;;
> >          *)
> >              exit
> >              ;;
> >      esac
> >  done
> >  
> > -RUNTIME_arch_run="./$TEST_DIR/run >> test.log"
> > +RUNTIME_arch_run="./$TEST_DIR/run $log_redir"
> >  config=$TEST_DIR/unittests.cfg
> >  rm -f test.log
> >  echo > test.log
> > diff --git a/scripts/pretty_print_stacks.py b/scripts/pretty_print_stacks.py
> > new file mode 100755
> > index 0000000..49564bd
> > --- /dev/null
> > +++ b/scripts/pretty_print_stacks.py
> > @@ -0,0 +1,61 @@
> > +#!/usr/bin/env python
> > +
> > +import re
> > +import subprocess
> > +import sys
> > +
> > +if len(sys.argv) != 2:
> > +    sys.stderr.write('usage: %s <kernel>\n' % sys.argv[0])
> > +    sys.exit(1)
> > +
> > +binary = sys.argv[1]
> > +
> > +# Subvert output buffering.
> > +def puts(string):
> > +    sys.stdout.write(string)
> > +    sys.stdout.flush()
> > +
> > +try:
> > +    while True:
> > +        # Subvert input buffering.
> > +        line = sys.stdin.readline()
> > +        if line == '':
> > +            break
> > +
> > +        if not line.strip().startswith('STACK:'):
> > +            puts(line)
> > +            continue
> > +
> > +        addrs = line.split()[1:]
> > +        # Output like this:
> > +        #        0x004002be: start64 at path/to/kvm-unit-tests/x86/cstart64.S:208
> > +        #         (inlined by) test_ept_violation at path/to/kvm-unit-tests/x86/vmx_tests.c:1719 (discriminator 1)
> > +        cmd = ['addr2line', '-e', binary, '-i', '-f', '--pretty', '--address']
> > +        cmd.extend(addrs)
> > +
> > +        p = subprocess.Popen(cmd, stdout=subprocess.PIPE)
> > +        out, err = p.communicate()
> > +        if p.returncode != 0:
> > +            puts(line)
> > +            continue
> > +
> > +        for line in out.splitlines():
> > +            m = re.match('(.*) at [^ ]*/kvm-unit-tests/([^ ]*):([0-9]+)(.*)', line)
> > +            if m is None:
> > +                puts('%s\n' % line)
> > +                continue
> > +
> > +            head, path, line, tail = m.groups()
> > +            line = int(line)
> > +            puts('%s at %s:%d%s\n' % (head, path, line, tail))
> > +            try:
> > +                lines = open(path).readlines()
> > +            except IOError:
> > +                continue
> > +            if line > 1:
> > +                puts('        %s\n' % lines[line - 2].rstrip())
> > +            puts('      > %s\n' % lines[line - 1].rstrip())
> > +            if line < len(lines):
> > +                puts('        %s\n' % lines[line].rstrip())
> > +except:
> > +    sys.exit(1)
> > 
> 
> For now I've committed only the script; I'd like Drew to take a look at
> run_tests.sh and see if it's possible/worthwhile to include the pretty
> printing script in mkstandalone.sh.  But even without integration in
> run_tests.sh the scripts is nice and useful.
> 
> Queued, will push tomorrow together with the rest.

It should be possible, just another "temp_file", I think. But then we
expect the standalone test to be executed somewhere with pyhon (likely)
and addr2line (not as likely). Also, without the source available, then
it probably isn't all the useful to the user executing the test, and
anybody they send the results to can copy+paste the backtrace line
directly into addr2line themselves.

Long story short, I vote we don't add it to mkstandalone.

Now, one addition that may make sense, wrt mkstandalone, is that we output
what HEAD was when mkstandalone was used to build the tests. That would be
useful just by itself to know what code is running, and extra useful when
using addr2line.

drew