[Bug tapsets/13074] New: Some nfs tapset probes broken under linux 3.1-rc1

[Bug tapsets/13074] New: Some nfs tapset probes broken under linux 3.1-rc1

[mjw at redhat dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=13074

             Bug #: 13074
           Summary: Some nfs tapset probes broken under linux 3.1-rc1
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: tapsets
        AssignedTo: systemtap@sourceware.org
        ReportedBy: mjw@redhat.com
    Classification: Unclassified


The following failures can be seen under 3.1.0-0.rc1.git1.1.fc17.x86_64:

Running /home/mark/src/systemtap/testsuite/buildok/nfs_proc-detailed.stp
starting /home/mark/src/systemtap/testsuite/buildok/nfs_proc-detailed.stp
spawn1 stap -p4
/home/mark/src/systemtap/testsuite/buildok/nfs_proc-detailed.stp
spawn stap -p4 /home/mark/src/systemtap/testsuite/buildok/nfs_proc-detailed.stp
semantic error: unable to find local 'task' near pc 0x7e5ee  in  nfs_read_done
f
s/nfs/proc.c ( (alternatives: $data): identifier '$task' at
/usr/local/install/s
ystemtap/share/systemtap/tapset/nfs_proc.stp:803:11
        source:         status = $task->tk_status
                              semantic error: unable to find local 'task' near
p
c 0x7e5ee  in  nfs_read_done fs/nfs/proc.c ( (alternatives: $data): identifier
'
$task' at
/usr/local/install/systemtap/share/systemtap/tapset/nfs_proc.stp:803:1
1

        source:         status = $task->tk_status
   ^
semantic error: unable to find local 'task' near pc 0x7e578  in  nfs_write_done 
fs/nfs/proc.c ( (alternatives: $data): identifier '$task' at :1039:11
        source:         status = $task->tk_status
                                 ^

                                 ^

semantic error: unable to find local 'task' near pc 0x7e578  in  nfs_write_done
fs/nfs/proc.c ( (alternatives: $data): identifier '$task' at :1039:11

        source:         status = $task->tk_status

                                 ^
semantic error: unable to find local 'task' near pc 0x848c0  in 
nfs3_write_done fs/nfs/nfs3proc.c ( (alternatives: $data): identifier '$task'
at :1070:11
        source:         status = $task->tk_status
                                 ^

semantic error: unable to find local 'task' near pc 0x848c0  in 
nfs3_write_done fs/nfs/nfs3proc.c ( (alternatives: $data): identifier '$task'
at :1070:11

        source:         status = $task->tk_status

                                 ^
Pass 2: analysis failed.  Try again with another '--vp 01' option.

Pass 2: analysis failed.  Try again with another '--vp 01' option.
wait results: 571 exp19 0 1
FAIL: buildok/nfs_proc-detailed.stp


Running /home/mark/src/systemtap/testsuite/buildok/nfsd-all-probes.stp
starting /home/mark/src/systemtap/testsuite/buildok/nfsd-all-probes.stp
spawn1 stap -wp4 /home/mark/src/systemtap/testsuite/buildok/nfsd-all-probes.stp
spawn stap -wp4 /home/mark/src/systemtap/testsuite/buildok/nfsd-all-probes.stp
semantic error: no match while resolving probe point nfsd.createv3
semantic error: no match while resolving probe point nfsd.createv3
semantic error: no match while resolving probe point nfsd.createv3.return

semantic error: no match while resolving probe point nfsd.createv3.return
Pass 2: analysis failed.  Try again with another '--vp 01' option.

Pass 2: analysis failed.  Try again with another '--vp 01' option.
wait results: 770 exp19 0 1
FAIL: buildok/nfsd-all-probes.stp
Running /home/mark/src/systemtap/testsuite/buildok/nfsd-detailed.stp
starting /home/mark/src/systemtap/testsuite/buildok/nfsd-detailed.stp
spawn1 stap -p4 /home/mark/src/systemtap/testsuite/buildok/nfsd-detailed.stp
spawn stap -p4 /home/mark/src/systemtap/testsuite/buildok/nfsd-detailed.stp
semantic error: no match while resolving probe point nfsd.createv3
semantic error: no match while resolving probe point nfsd.createv3.return
semantic error: no match while resolving probe point nfsd.createv3

semantic error: no match while resolving probe point nfsd.createv3.return
Pass 2: analysis failed.  Try again with another '--vp 01' option.

Pass 2: analysis failed.  Try again with another '--vp 01' option.
wait results: 774 exp19 0 1
FAIL: buildok/nfsd-detailed.stp

-- 
Configure bugmail: http://sourceware.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

[Bug tapsets/13074] Some nfs tapset probes broken under linux 3.1-rc1

[dsmith at redhat dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=13074

David Smith <dsmith at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |dsmith at redhat dot com

--- Comment #1 from David Smith <dsmith at redhat dot com> 2011-08-11 20:41:55 UTC ---
This one isn't a result of kernel changes, but a result of bad debuginfo (or
systemtap's understanding of debuginfo).  Systemtap doesn't think the inline
version of these functions have the '$task' parameter:

# stap -L 'module("nfs").function("nfs_read_done").*'
module("nfs").function("nfs_read_done@fs/nfs/proc.c:631").call $task:struct
rpc_task* $data:struct nfs_read_data*
module("nfs").function("nfs_read_done@fs/nfs/proc.c:631").inline $data:struct
nfs_read_data*
module("nfs").function("nfs_read_done@fs/nfs/proc.c:631").return $return:int
$task:struct rpc_task* $data:struct nfs_read_data*

-- 
Configure bugmail: http://sourceware.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

[Bug tapsets/13074] Some nfs tapset probes broken under linux 3.1-rc1

[mjw at redhat dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=13074

--- Comment #2 from Mark Wielaard <mjw at redhat dot com> 2011-08-15 13:17:47 UTC ---
I added some hints and tips on investigating missing dwarf locations at:
http://sourceware.org/systemtap/wiki/TipContextVariables
I used this bug as example:

 If you want to help debug why the location information is missing (for a nice
and juicy gcc bug report for example) then try something like (lets assume we
are looking for the task parameter from the nfs_read_done function in the nfs
module):

   * {{{eu-readelf -N --debug-dump=info
/usr/lib/debug/lib/modules/3.1.0-0.rc1.git1.1.fc17.x86_64/kernel/fs/nfs/nfs.ko.debug
| less}}}
   * Look for the function: {{{
  [10974b]    subprogram
              name                 (strp) "nfs_read_done"
              decl_file            (data1) 1
              decl_line            (data2) 631
              prototyped           (flag_present) Yes
              type                 (ref4) [ f3cc0]
              inline               (data1) inlined (1)
              sibling              (ref4) [109775]
  [10975c]      formal_parameter
                name                 (strp) "task"
                decl_file            (data1) 1
                decl_line            (data2) 631
                type                 (ref4) [ fd230]
  [109768]      formal_parameter
                name                 (strp) "data"
                decl_file            (data1) 1
                decl_line            (data2) 631
   }}}
   * Notice the call is inlined. So we want to look for reference to either the
subprogram [10974b] or the actual formal_parameter [10975c].
   * We find the formal_parameter a little later: {{{
    [10a1b1]      formal_parameter
                abstract_origin      (ref4) [10975c]
                location             (sec_offset) location list [ 23713]
   }}}
   The location attribute is there, which is good (if it is missing, we already
have our problem).
   * Now look at the location list with {{{eu-readelf --debug-dump=loc
/usr/lib/debug/lib/modules/3.1.0-0.rc1.git1.1.fc17.x86_64/kernel/fs/nfs/nfs.ko.debug
| less}}} and search for offset 23713: {{{
  [ 23713]  .text+0x00000000000002bd
<nfs_init_server_rpcclient+0x35>...text+0x00000000000002f0
<nfs_init_server_rpcclient+0x68>
  [   0] reg5
            .text+0x00000000000002f0
<nfs_init_server_rpcclient+0x68>...text+0x0000000000000356
<nfs_init_server_rpcclient+0xce>
  [   0] reg12
            .text+0x0000000000000356
<nfs_init_server_rpcclient+0xce>...text+0x000000000000035d
<nfs_init_server_rpcclient+0xd5>
  [   0] GNU_entry_value:
        [   0] reg5
        [   3] stack_value
   }}}
   So this was inlined into the nfs_init_server_rpcclient function. Note there
are 3 address ranges with 3 different location expressions for finding the task
parameter.
   * Now figure out whether these locations match your probe point address
and/or the location expression makes sense. If anything looks odd or is missing
file a gcc bug report. If everything looks like stap should be able to figure
out, file a systemtap bug report. (Note that in this case it might be the last
location expression, stap currently doesn't deal with DW_OP_GNU_entry_value -
which here says that task can be found in the last code range by taking the
value of reg5 upon entering this function.)

-- 
Configure bugmail: http://sourceware.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

[Bug tapsets/13074] Some nfs tapset probes broken under linux 3.1-rc1

[dsmith at redhat dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=13074

--- Comment #3 from David Smith <dsmith at redhat dot com> 2013-01-10 19:51:24 UTC ---
Looking at today's rawhide kernel (3.8.0-0.rc2.git3.1.fc19.x86_64), things are
even more odd:

====
# stap -L 'module("nfsv2").function("nfs_proc_lookup").*'
module("nfsv2").function("nfs_proc_lookup@fs/nfs/proc.c:148").call $arg:struct
nfs_diropargs $res:struct nfs_diropok $msg:struct rpc_message
module("nfsv2").function("nfs_proc_lookup@fs/nfs/proc.c:148").return
$return:int $arg:struct nfs_diropargs $res:struct nfs_diropok $msg:struct
rpc_message
====

Here's the source to nfs_proc_lookup. Looking at this, it appears that stap has
confused local variables for parameters:

====
static int                                                                      
nfs_proc_lookup(struct inode *dir, struct qstr *name,                           
                struct nfs_fh *fhandle, struct nfs_fattr *fattr)                
{                                                                               
        struct nfs_diropargs    arg = {                                         
                .fh             = NFS_FH(dir),                                  
                .name           = name->name,                                   
                .len            = name->len                                     
        };                                                                      
        struct nfs_diropok      res = {                                         
                .fh             = fhandle,                                      
                .fattr          = fattr                                         
        };                                                                      
        struct rpc_message msg = {                                              
                .rpc_proc       = &nfs_procedures[NFSPROC_LOOKUP],              
                .rpc_argp       = &arg,                                         
                .rpc_resp       = &res,                                         
        };                                                                      
====

Here's what "eu-readelf -N --debug-dump=info" reports for 'nfs_proc_lookup':

====
 [ 31c90]    subprogram
             name                 (strp) "nfs_proc_lookup"
             decl_file            (data1) 1
             decl_line            (data1) 148
             prototyped           (flag_present) Yes
             type                 (ref4) [ 18e99]
             low_pc               (addr) .text+0x0000000000000580
             high_pc              (addr) .text+0x000000000000063e
             frame_base           (exprloc)
              [   0] call_frame_cfa
             GNU_all_call_sites   (flag_present) Yes
             sibling              (ref4) [ 31dd5]
 [ 31cb1]      formal_parameter
               name                 (string) "dir"
               decl_file            (data1) 1
               decl_line            (data1) 148
               type                 (ref4) [ 1e9f9]
               location             (sec_offset) location list [   de7]
 [ 31cc0]      formal_parameter
               name                 (strp) "name"
               decl_file            (data1) 1
               decl_line            (data1) 148
               type                 (ref4) [ 1ed6f]
               location             (sec_offset) location list [   e5c]
 [ 31ccf]      formal_parameter
               name                 (strp) "fhandle"
               decl_file            (data1) 1
               decl_line            (data1) 149
               type                 (ref4) [ 2ed02]
               location             (sec_offset) location list [   e95]
 [ 31cde]      formal_parameter
               name                 (strp) "fattr"
               decl_file            (data1) 1
               decl_line            (data1) 149
               type                 (ref4) [ 2e617]
               location             (sec_offset) location list [   f21]
 [ 31ced]      variable
               name                 (string) "arg"
               decl_file            (data1) 1
               decl_line            (data1) 151
               type                 (ref4) [ 2f1a1]
               location             (exprloc)
                [   0] fbreg -88
 [ 31cfc]      variable
               name                 (string) "res"
               decl_file            (data1) 1
               decl_line            (data1) 156
               type                 (ref4) [ 2f2f5]
               location             (exprloc)
                [   0] fbreg -104
 [ 31d0b]      variable
               name                 (string) "msg"
               decl_file            (data1) 1
               decl_line            (data1) 160
               type                 (ref4) [ 21ea5]
               location             (exprloc)
                [   0] fbreg -64
====

Here's the relevant 'eu-readelf --debug-dump=loc' data:

====
 [   de7]  .text+0x0000000000000555
<nfs_proc_readlink+0x85>...text+0x00000000000005ab <nfs_proc_lookup+0x2b> [  
0] reg5
           .text+0x00000000000005ab
<nfs_proc_lookup+0x2b>...text+0x00000000000005d6 <nfs_proc_lookup+0x56> [   0]
reg3
           .text+0x00000000000005d6
<nfs_proc_lookup+0x56>...text+0x00000000000005e1 <nfs_proc_lookup+0x61> [   0]
GNU_entry_value:
       [   0] reg5
                                                  [   3] stack_value
           .text+0x00000000000005e1
<nfs_proc_lookup+0x61>...text+0x00000000000005fc <nfs_proc_lookup+0x7c> [   0]
reg3
           .text+0x00000000000005fc
<nfs_proc_lookup+0x7c>...text+0x000000000000060e <nfs_proc_lookup+0x8e> [   0]
GNU_entry_value:
       [   0] reg5
                                                  [   3] stack_value
 [   e5c]  .text+0x0000000000000555
<nfs_proc_readlink+0x85>...text+0x0000000000000582 <nfs_proc_lookup+0x2> [   0]
reg4
           .text+0x0000000000000582
<nfs_proc_lookup+0x2>...text+0x000000000000060e <nfs_proc_lookup+0x8e> [   0]
GNU_entry_value:
       [   0] reg4
                                                  [   3] stack_value
 [   e95]  .text+0x0000000000000555
<nfs_proc_readlink+0x85>...text+0x0000000000000577 [   0] reg1
           .text+0x0000000000000577...text+0x000000000000058e
<nfs_proc_lookup+0xe> [   0] fbreg -104
           .text+0x000000000000058e
<nfs_proc_lookup+0xe>...text+0x00000000000005ab <nfs_proc_lookup+0x2b> [   0]
breg1 0
           .text+0x00000000000005ab
<nfs_proc_lookup+0x2b>...text+0x00000000000005e1 <nfs_proc_lookup+0x61> [   0]
GNU_entry_value:
       [   0] reg1
                                                  [   3] stack_value
           .text+0x00000000000005e1
<nfs_proc_lookup+0x61>...text+0x00000000000005f5 <nfs_proc_lookup+0x75> [   0]
breg1 0
           .text+0x00000000000005f5
<nfs_proc_lookup+0x75>...text+0x000000000000060e <nfs_proc_lookup+0x8e> [   0]
GNU_entry_value:
       [   0] reg1
                                                  [   3] stack_value
           .text+0x00000000000005e1
<nfs_proc_lookup+0x61>...text+0x00000000000005f5 <nfs_proc_lookup+0x75> [   0]
breg1 0
           .text+0x00000000000005f5
<nfs_proc_lookup+0x75>...text+0x000000000000060e <nfs_proc_lookup+0x8e> [   0]
GNU_entry_value:
       [   0] reg1
                                                  [   3] stack_value
 [   f21]  .text+0x0000000000000555
<nfs_proc_readlink+0x85>...text+0x00000000000005ab <nfs_proc_lookup+0x2b> [  
0] reg2
           .text+0x00000000000005ab
<nfs_proc_lookup+0x2b>...text+0x00000000000005e1 <nfs_proc_lookup+0x61> [   0]
GNU_entry_value:
       [   0] reg2
                                                  [   3] stack_value
           .text+0x00000000000005e1
<nfs_proc_lookup+0x61>...text+0x00000000000005f5 <nfs_proc_lookup+0x75> [   0]
reg2
           .text+0x00000000000005f5
<nfs_proc_lookup+0x75>...text+0x000000000000060e <nfs_proc_lookup+0x8e> [   0]
GNU_entry_value:
       [   0] reg2
                                                  [   3] stack_value
 [   f83]  .text+0x00000000000005d6
<nfs_proc_lookup+0x56>...text+0x00000000000005d8 <nfs_proc_lookup+0x58> [   0]
reg0
           .text+0x00000000000005d8
<nfs_proc_lookup+0x58>...text+0x00000000000005df <nfs_proc_lookup+0x5f> [   0]
reg3
           .text+0x00000000000005df
<nfs_proc_lookup+0x5f>...text+0x00000000000005e1 <nfs_proc_lookup+0x61> [   0]
reg0
           .text+0x00000000000005fc
<nfs_proc_lookup+0x7c>...text+0x0000000000000607 <nfs_proc_lookup+0x87> [   0]
reg0
           .text+0x0000000000000607
<nfs_proc_lookup+0x87>...text+0x000000000000060e <nfs_proc_lookup+0x8e> [   0]
reg3
 [   ff2]  .text+0x00000000000005b3
<nfs_proc_lookup+0x33>...text+0x00000000000005d6 <nfs_proc_lookup+0x56> [   0]
reg3
           .text+0x00000000000005d6
<nfs_proc_lookup+0x56>...text+0x00000000000005e1 <nfs_proc_lookup+0x61> [   0]
GNU_entry_value:
       [   0] reg5
                                                  [   3] stack_value
           .text+0x00000000000005fc
<nfs_proc_lookup+0x7c>...text+0x000000000000060e <nfs_proc_lookup+0x8e> [   0]
GNU_entry_value:
       [   0] reg5
                                                  [   3] stack_value
====

Mark, got any thoughts as to what is going on here?

-- 
Configure bugmail: http://sourceware.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

[Bug tapsets/13074] Some nfs tapset probes broken under linux 3.1-rc1

[mjw at redhat dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=13074

--- Comment #4 from Mark Wielaard <mjw at redhat dot com> 2013-01-11 21:48:31 UTC ---
(In reply to comment #3)
> Looking at today's rawhide kernel (3.8.0-0.rc2.git3.1.fc19.x86_64), things are
> even more odd:
> 
> ====
> # stap -L 'module("nfsv2").function("nfs_proc_lookup").*'
> module("nfsv2").function("nfs_proc_lookup@fs/nfs/proc.c:148").call $arg:struct
> nfs_diropargs $res:struct nfs_diropok $msg:struct rpc_message
> module("nfsv2").function("nfs_proc_lookup@fs/nfs/proc.c:148").return
> $return:int $arg:struct nfs_diropargs $res:struct nfs_diropok $msg:struct
> rpc_message
> ====
> 
> Here's the source to nfs_proc_lookup. Looking at this, it appears that stap has
> confused local variables for parameters:

Note that for -L it doesn't matter (to stap) whether some accessible local is a
parameter or a variable. It just matters if it can use the DWARF to access it
at the probe location.

> Mark, got any thoughts as to what is going on here?

In this case $arg, $rest and $msg (local variables) have simple DWARF location
expressions (basically telling where on the stack they can be found). So they
are listed. While the actual parameters seem to have more complex location
descriptions (involving GNU_entry_val) so are deemed inaccessible, so most
aren't listed.

-- 
Configure bugmail: http://sourceware.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

[Bug tapsets/13074] Some nfs tapset probes broken under linux 3.1-rc1

[dsmith at redhat dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=13074

--- Comment #5 from David Smith <dsmith at redhat dot com> 2013-01-11 22:41:32 UTC ---
(In reply to comment #4)
> (In reply to comment #3)
> > Mark, got any thoughts as to what is going on here?
> 
> In this case $arg, $rest and $msg (local variables) have simple DWARF location
> expressions (basically telling where on the stack they can be found). So they
> are listed. While the actual parameters seem to have more complex location
> descriptions (involving GNU_entry_val) so are deemed inaccessible, so most
> aren't listed.

How difficult would supporting GNU_entry_val be? It seems like it might be the
best way forward, unless you've got other ideas.

-- 
Configure bugmail: http://sourceware.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

[Bug tapsets/13074] Some nfs tapset probes broken under linux 3.1-rc1

[mjw at redhat dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=13074

--- Comment #6 from Mark Wielaard <mjw at redhat dot com> 2013-01-11 22:58:48 UTC ---
(In reply to comment #5)

> How difficult would supporting GNU_entry_val be?

It is on my list of tasks for this month. It needs support on elfutils to get
at the entry_val block and in systemtap to provide the entry_val values to
evaluate the block with.

I admit I am slightly surprised we seem to hit this with .call probes, since I
had assumed the actual parameters at the call probe location would still be
"simple". So another thing to look at is why the probe location address seems
to be so late.

-- 
Configure bugmail: http://sourceware.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

[Bug tapsets/13074] Some nfs tapset probes broken under linux 3.1-rc1

[fche at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=13074

Frank Ch. Eigler <fche at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
                 CC|                            |fche at redhat dot com
         Resolution|---                         |WORKSFORME

--- Comment #7 from Frank Ch. Eigler <fche at redhat dot com> ---
recent kernels & distros & tapsets work better here

-- 
You are receiving this mail because:
You are the assignee for the bug.