Show inlined functions with bt-akaros.sh (kernel)
authorBarret Rhoden <brho@cs.berkeley.edu>
Fri, 15 Nov 2019 01:58:19 +0000 (20:58 -0500)
committerBarret Rhoden <brho@cs.berkeley.edu>
Fri, 15 Nov 2019 01:58:19 +0000 (20:58 -0500)
I noticed syzkaller was printing out additional backtrace lines with
info about inlining functions.  addr2line does that for us, spitting the
info out on two lines.  With a little Bash magic, we can parse those
lines too.

Now something like this:

 #04 [<0xffffffffc2059e3e>] in __try_wait_any.isra.7
 #05 [<0xffffffffc205bf3a>] in sys_waitpid
 #06 [<0xffffffffc205c849>] in syscall

will show up as:

 #04 [<0xffffffffc2059e3e>] in __try_wait_any() at kern/src/syscall.c:1221
 #05 [<0xffffffffc205bf3a>] in wait_any() at kern/src/syscall.c:1286
 #05 [<   (inlined by)   >] in sys_waitpid() at kern/src/syscall.c:1329
 #06 [<0xffffffffc205c849>] in syscall() at kern/src/syscall.c:2582

Frame 5 is repeated twice.  The actual address, which the kernel's
symtab says in in sys_waitpid(), is actually in wait_any().  Both the
inlined function (wait_any()) and the function it is in are reported.

The previous version of bt_akaros was printing the correct line number
(1286); you'd just have to notice when you opened the code that it is in
wait_any(), which might not be obvious if you're looking at a slightly
different kernel source.

Overall, this gives us more info when processing backtraces in that we
can see the inlining and call graph.  For example, here's a backtrace
syzkaller caught:

 #03 [<0xffffffffc20496db>] in kref_put
 #04 [<0xffffffffc204d520>] in proc_destroy
 #05 [<0xffffffffc2058c36>] in sys_proc_destroy

That doesn't tell us much.  It is much better with inlining:

 #03 [<0xffffffffc20496db>] in kref_put at include/kref.h:68
 #04 [<     [inline]     >] in proc_decref at src/process.c:587
 #04 [<     [inline]     >] in proc_disown_children at src/process.c:853
 #04 [<0xffffffffc204d520>] in proc_destroy at src/process.c:932
 #05 [<0xffffffffc2058c36>] in sys_proc_destroy at src/syscall.c:852

Note this is independent of CONFIG_BETTER_BACKTRACES, which just sets
-fno-optimize-sibling-calls.  This change is all about getting more info
from the backtrace the kernel spits out.  BETTER_BACKTRACES is about
making the kernel spit out more frames.

Signed-off-by: Barret Rhoden <brho@cs.berkeley.edu>
scripts/bt-akaros.sh

index d1b13b0..7bf6227 100755 (executable)
@@ -24,11 +24,27 @@ kernel_line() {
        line=$1
 
        addr=`echo $line | cut -c 7-25`
+       frame_num=`echo $line | cut -f 1 -d ' '`
 
-       echo -n $line " "
-       # sed cleans out build paths.  All kernel files have 'kern', unlike
-       # arbitrary user binaries.
-       addr2line -e $KERNEL_BINARY $addr | sed 's/^.*kern\//at kern\//'
+       IFS=' '
+       addr2line -afip -e $KERNEL_BINARY $addr | while read -ra RET
+       do
+               if [ "${RET[0]}" == "(inlined" ]; then
+                       # (inlined by) with spaces to line up with a 64 bit addr
+                       addr="   ${RET[0]} ${RET[1]}   "
+                       func="${RET[2]}"
+                       srcl="${RET[4]}"
+               else
+                       addr="${RET[0]}"
+                       addr="${addr%?}"        # drop the trailing ':'
+                       func="${RET[1]}"
+                       srcl="${RET[3]}"
+               fi
+               # sed cleans out build paths.  All kernel files start with
+               # '/kern', unlike arbitrary user binaries.
+               srcl=`echo $srcl | sed 's/^.*\/kern\//kern\//'`
+               echo "$frame_num [<$addr>] in ${func}() at $srcl"
+       done
 }
 
 user_line() {