Review of the systemtap examples testsuite results x86 Fedora rawhide

Review of the systemtap examples testsuite results x86 Fedora rawhide

[William Cohen]

Now that systemtap is working with 5.0.0-rcx kernel took the time to run the
systemtap examples to see what failed.

The following two tests are failing because "vitural memory exhausted"
Both are using --all-modules. There are some other test other PASS:
but it looks like they result in smaller stap-symbols.h files.  These
particular tests look to be because stap-symbols.h files are huge,
over 70MB.  This fail might be more of a result of the guest VM having
2GB of RAM. However, not sure why there is such variations in the
in the size of the stap-symbols.h files

FAIL: systemtap.examples/profiling/fileline-profile run
FAIL: systemtap.examples/profiling/periodic build


Kernel commit 23c9deeb328 eliminates all the FAN_ALL_* defines causing
FAN_ALL_CLASS_BITS to be undefined. This commit is also in the 4.20
kernels, so the errsnoop and strace examples will also break on Fedora
29/28.  _fanotify_init_flags_str function in
tapset/linux/aux_syscalls.stp will need to be fixed up.

FAIL: systemtap.examples/process/errsnoop build
FAIL: systemtap.examples/process/strace build


The following two tests seem to be having issues with the
kernel.statement() on do_sys_open being used for them.  Both get
"inconsistent relocation address".

FAIL: systemtap.examples/general/varwatch build
FAIL: systemtap.examples/general/whythefail build


The following test appears not to go down some other function other
than the vfs_* functions being currently monitored.  This does work on
RHEL7.  Looking through the list of EXPORT_SYMBOLS(vfs_*) in
linux/fs/namei.c it looks like vfs_tmpfile or vfs_mkobj are likely
missing probes:

FAIL: systemtap.examples/general/badname run


The syscall.ptrace probe point is now using the nodwarf version, so
$request target variable isn't available

FAIL: systemtap.examples/process/noptrace build


Lots of kernel internal ABI changes making the following fail to build:

FAIL: systemtap.examples/process/pfiles build

-Will

Re: Review of the systemtap examples testsuite results x86 Fedora rawhide

[William Cohen]

On 2/6/19 4:41 PM, William Cohen wrote:
> Now that systemtap is working with 5.0.0-rcx kernel took the time to run the
> systemtap examples to see what failed.
> 
> The following two tests are failing because "vitural memory exhausted"
> Both are using --all-modules. There are some other test other PASS:
> but it looks like they result in smaller stap-symbols.h files.  These
> particular tests look to be because stap-symbols.h files are huge,
> over 70MB.  This fail might be more of a result of the guest VM having
> 2GB of RAM. However, not sure why there is such variations in the
> in the size of the stap-symbols.h files
> 
> FAIL: systemtap.examples/profiling/fileline-profile run
> FAIL: systemtap.examples/profiling/periodic build

When running the fileline-profile see cc1 get way up there in memory use on successful run on a machine with ample resources:

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                            
17936 root      20   0 3013476   2.4g  12484 R 100.0   7.6   0:23.33 cc1          

similarly for periodic.stp see:

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                                
21631 root      20   0 3656892   2.7g  21588 R  99.7   8.8   0:29.40 cc1  

> 
>> Kernel commit 23c9deeb328 eliminates all the FAN_ALL_* defines causing
> FAN_ALL_CLASS_BITS to be undefined. This commit is also in the 4.20
> kernels, so the errsnoop and strace examples will also break on Fedora
> 29/28.  _fanotify_init_flags_str function in
> tapset/linux/aux_syscalls.stp will need to be fixed up.
> 
> FAIL: systemtap.examples/process/errsnoop build
> FAIL: systemtap.examples/process/strace build

Both errsnoop and strace are working now with systemtap git commits:
4e76869512d2d05fc3347861bdeed92395e34d63
1ac5a4499ecc17f612a94bf4dff39ba90d4cd532

However, noticed that there appears to be some nd_syscall.*.retrun probes missing retstr given the following warnings when running strace.stp:

WARNING: never-assigned local variable 'retstr' (similar: argstr, status, name, _target_set, thread_argstr): identifier 'retstr' at strace.stp:49:38
 source:     report(name,thread_argstr[tid()],retstr)
                                              ^
WARNING: never-assigned local variable 'retstr' (similar: argstr, status, name, _target_set, thread_argstr): identifier 'retstr' at :49:38
 source:     report(name,thread_argstr[tid()],retstr)
                                              ^
WARNING: never-assigned local variable 'retstr' (similar: argstr, status, name, _target_set, thread_argstr): identifier 'retstr' at :49:38
 source:     report(name,thread_argstr[tid()],retstr)
                                              ^
WARNING: never-assigned local variable 'retstr' (similar: argstr, status, name, _target_set, thread_argstr): identifier 'retstr' at :49:38
 source:     report(name,thread_argstr[tid()],retstr)
   
> 
> 
> The following two tests seem to be having issues with the
> kernel.statement() on do_sys_open being used for them.  Both get
> "inconsistent relocation address".
> 
> FAIL: systemtap.examples/general/varwatch build
> FAIL: systemtap.examples/general/whythefail build
> 
> 
> The following test appears not to go down some other function other
> than the vfs_* functions being currently monitored.  This does work on
> RHEL7.  Looking through the list of EXPORT_SYMBOLS(vfs_*) in
> linux/fs/namei.c it looks like vfs_tmpfile or vfs_mkobj are likely
> missing probes:
> 
> FAIL: systemtap.examples/general/badname run

Found that badname.stp last worked in linux 4.6 and was broken in 4.7.  Did a kernel bisect today and found that the following kernel commit caused this example to stop working:

commit 6ac087099edf09ca357e2f765e3e24677543897c
Author: Al Viro <viro@zeniv.linux.org.uk>
Date:   Tue Apr 26 00:02:50 2016 -0400

    path_openat(): take O_PATH handling out of do_last()
    
    do_last() and lookup_open() simpler that way and so does O_PATH
    itself.  As it bloody well should: we find what the pathname
    resolves to, same way as in stat() et.al. and associate it with
    FMODE_PATH struct file.
    
    Signed-off-by: Al Viro <viro@zeniv.linux.org.uk>

> 
> 
> The syscall.ptrace probe point is now using the nodwarf version, so
> $request target variable isn't available
> 
> FAIL: systemtap.examples/process/noptrace build
> 
> 
> Lots of kernel internal ABI changes making the following fail to build:
> 
> FAIL: systemtap.examples/process/pfiles build
> 
> -Will
> 

Re: Review of the systemtap examples testsuite results x86 Fedora rawhide

[William Cohen]

On 2/6/19 4:41 PM, William Cohen wrote:


> The following two tests seem to be having issues with the
> kernel.statement() on do_sys_open being used for them.  Both get
> "inconsistent relocation address".
> 
> FAIL: systemtap.examples/general/varwatch build
> FAIL: systemtap.examples/general/whythefail build

There seems to be some issue with the probing each of the line number in the function:

From systemtap.log for varwatch:

attempting command stap -wp4 varwatch.stp 'kernel.statement("do_sys_open@fs/open.c:*")' '$$vars'
OUT semantic error: inconsistent relocation address: keyword at varwatch.stp:5:1
        source: probe $1 {
                ^

Pass 2: analysis failed.  [man error::pass2]
Number of similar error messages suppressed: 14.
Rerun with -v to see them.
child process exited abnormally
RC 1
FAIL: systemtap.examples/general/varwatch build

What is meant by "inconsistent relocation address"?  What is that check in tapsets.cxx trying to address?

I ran the following command on 5.0.0-0.rc6.git0.1.fc30.x86_64 below.  There are lines of code that are not listed: 1051, 1054, 1057, and 1059.  However, trying to specify most of these lines that match the wildcard below explicitly yield the "inconsistent relocation address" error.  Looking through dejazilla information for varwatch test results the 4.15 kernels seemed to passed, but the test(s) started failing with linux-4.17.0 about 7 months ago. It might be something due to gcc 8 as I didn't find any failures using GCC 7 compilers in the queries:

gcc8 based (https://web.elastic.org/~dejazilla/view.php?_offset=0&_limit=400&_sort=1A&summary=&age=&rg=&tool=&variant=&versions=LIKE+%27%25kernel%3A4.1%25gcc%3A8.%25%27&testcase=LIKE+%27%25varwatch%25build%25%27&result=)
gcc7 based (https://web.elastic.org/~dejazilla/view.php?_offset=0&_limit=400&_offset=0&summary=&age=&rg=&tool=&variant=&versions=LIKE+%27%25kernel%3A4.1%25gcc%3A7.%25%27&testcase=LIKE+%27%25varwatch%25build%25%27&result=)
-Will


$ stap -L 'kernel.statement("do_sys_open@fs/open.c:*")'
kernel.statement("do_sys_open@fs/open.c:1049") $dfd:int $filename:char const* $flags:int $mode:umode_t $op:struct open_flags
kernel.statement("do_sys_open@fs/open.c:1050") $dfd:int $filename:char const* $flags:int $mode:umode_t $op:struct open_flags
kernel.statement("do_sys_open@fs/open.c:1052") $dfd:int $filename:char const* $flags:int $mode:umode_t $op:struct open_flags $fd:int
kernel.statement("do_sys_open@fs/open.c:1055") $dfd:int $filename:char const* $flags:int $mode:umode_t $op:struct open_flags
kernel.statement("do_sys_open@fs/open.c:1058") $dfd:int $filename:char const* $flags:int $mode:umode_t $op:struct open_flags $fd:int $tmp:struct filename*
kernel.statement("do_sys_open@fs/open.c:1061") $dfd:int $filename:char const* $flags:int $mode:umode_t $op:struct open_flags $fd:int $tmp:struct filename*
kernel.statement("do_sys_open@fs/open.c:1062") $dfd:int $filename:char const* $flags:int $mode:umode_t $op:struct open_flags $fd:int $tmp:struct filename*
kernel.statement("do_sys_open@fs/open.c:1063") $dfd:int $filename:char const* $flags:int $mode:umode_t $op:struct open_flags $fd:int $tmp:struct filename*
kernel.statement("do_sys_open@fs/open.c:1064") $f:struct file* $dfd:int $filename:char const* $flags:int $mode:umode_t $op:struct open_flags $fd:int $tmp:struct filename*
kernel.statement("do_sys_open@fs/open.c:1065") $f:struct file* $dfd:int $filename:char const* $flags:int $mode:umode_t $op:struct open_flags $fd:int $tmp:struct filename*
kernel.statement("do_sys_open@fs/open.c:1066") $f:struct file* $dfd:int $filename:char const* $flags:int $mode:umode_t $op:struct open_flags $fd:int $tmp:struct filename*
kernel.statement("do_sys_open@fs/open.c:1068") $f:struct file* $dfd:int $filename:char const* $flags:int $mode:umode_t $op:struct open_flags $fd:int $tmp:struct filename*
kernel.statement("do_sys_open@fs/open.c:1069") $f:struct file* $dfd:int $filename:char const* $flags:int $mode:umode_t $op:struct open_flags $fd:int $tmp:struct filename*
kernel.statement("do_sys_open@fs/open.c:1072") $dfd:int $filename:char const* $flags:int $mode:umode_t $op:struct open_flags $fd:int $tmp:struct filename*
kernel.statement("do_sys_open@fs/open.c:1073") $dfd:int $filename:char const* $flags:int $mode:umode_t $op:struct open_flags $fd:int $tmp:struct filename*
kernel.statement("do_sys_open@fs/open.c:1074") $dfd:int $filename:char const* $flags:int $mode:umode_t $op:struct open_flags