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
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*
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.)
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?
(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.
(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.
(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.
recent kernels & distros & tapsets work better here