Re: Failures with exelib.exp testcase (was Re: minutes 2010-08-19)

["K.Prasad" <prasad at linux dot vnet dot ibm dot com>]

On Tue, Jan 18, 2011 at 02:30:36PM +0100, Mark Wielaard wrote:
> On Tue, 2011-01-18 at 18:38 +0530, K.Prasad wrote:
> > appears that the "make RUNTESTFLAGS='exelib.exp' installcheck" is
> > failing because of unmatched symbol names....(a snippet of 
> > systemtap.log pasted below)
> > On the other hand, probing a simple helloworld.c program also results in
> > similar output
> > 
> > #include <stdio.h>
> > 
> > __attribute__((noinline))
> > void print_hw()
> > {
> > 	printf("Hello world\n");
> > }
> > 
> > int main()
> > {
> > 	print_hw();
> > 	return 0;
> > }
> > 
> > # stap -k -e 'probe process("/home/prasadkr/helloworld").function("print_hw") { printf("0x%x : %s\n", uaddr(), usymdata(uaddr())) }' -c ./helloworld
> > Hello world
> > 0x10000530 : 00000011.plt_call.__libc_start_main@@GLIBC_2.3+0+0x188/0x350 [/home/prasadkr/helloworld]
> > Keeping temporary directory "/tmp/stapQw4jDx"
> > 
> > However, it looks like the corresponding stap-symbols.h appears fine
> > (with the function names intact), so it is not clear where the problem
> > lies (whether the issue is insufficient unwind information or incorrect
> > symbol names or both). I've attached the same for your reference.
> 
> That shows something is definitely wrong with either the symbol address
> map or getting the current pc of the probed task. As you can see from
> the table, the mapping from address to symbol is actually correct:
> 
> static struct _stp_symbol _stp_module_0_symbols_0[] = {
> #ifdef STP_NEED_SYMBOL_DATA
>   { 0x10000390, "00000011.plt_call.puts@@GLIBC_2.3+0" },
>   { 0x100003a8, "00000011.plt_call.__libc_start_main@@GLIBC_2.3+0" },
>   { 0x100006f8, "__glink_PLTresolve" },
>   { 0x10000788, "_IO_stdin_used" },
>   { 0x10000790, "__dso_handle" },
>   { 0x10000840, "__FRAME_END__" },
>   { 0x10010844, "__init_array_start" },
>   { 0x10010848, "__CTOR_LIST__" },
>   { 0x10010850, "__CTOR_END__" },
>   { 0x10010858, "__DTOR_LIST__" },
>   { 0x10010860, "__DTOR_END__" },
>   { 0x10010868, "__JCR_END__" },
>   { 0x10010870, "_DYNAMIC" },
>   { 0x100109e0, "__data_start" },
>   { 0x10010a20, "_start" },
>   { 0x10010a30, "_init" },
>   { 0x10010a40, "_fini" },
>   { 0x10010a50, "__do_global_dtors_aux" },
>   { 0x10010a60, "frame_dummy" },
>   { 0x10010a70, "print_hw" },
>   { 0x10010a80, "main" },
>   { 0x10010a90, "__libc_csu_fini" },
>   { 0x10010aa0, "__libc_csu_init" },
>   { 0x10010ab0, "__do_global_ctors_aux" },
>   { 0x10010b08, "_edata" },
>   { 0x10010b50, "completed.6897" },
>   { 0x10010b58, "dtor_idx.6899" },
> #endif /* STP_NEED_SYMBOL_DATA */
> };
> 
> The address that uaddr() gives us is 0x10000530, which indeed is 0x188
> bytes after the start of symbol
> "00000011.plt_call.__libc_start_main@@GLIBC_2.3+0".
> 
> So either we are probing at the wrong address, or uaddr() is returning
> the wrong address from the user probe context.
> 
> Could you run the helloworld example with a couple of -vv arguments so
> we can see where it is placing the actual probes? We are looking for
> something like the following output in Pass 1:
> 
> probe print_hw@/home/mark/src/tests/helloworld.c:4
> process=/usr/local/src/tests/helloworld reloc=.absolute pc=0x4004c4
>

It appears that the probe is placed on top of the stack...pasting the
relevant log here (while complete screen logs are attached).

selected function print_hw
prologue searching function 'print_hw' 0x10000530-0x10000570@/home/prasadkr/helloworld.c:4
checking line record 0x10000530@/home/prasadkr/helloworld.c:5
prologue found function 'print_hw' (naked) = 0x10000530
probe print_hw@/home/prasadkr/helloworld.c:4 process=/home/prasadkr/helloworld reloc=.absolute pc=0x10000530

Attachment: helloworld_logs.txt
Description: Text document