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

[Mark Wielaard <mjw at redhat dot com>]

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)
> 
> print_ustack exe 1^M
>  0x00000000100006a0 : 00000011.plt_call.__libc_start_main@@GLIBC_2.3+0+0x188/0x3b0 [/usr/share/systemtap/testsuite/uprobesgcc-O3default-debug-uprobeslibgcc-O3default-debug_exe]^M
> 
> I also happen to find that the backtrace doesn't contain any symbol
> beyond the top of the stack, which probably indicates that the frame
> pointer information for full stack unwinding is missing in which case
> implementation of dwarf unwinding may be required. Kindly let us know
> if this is the case.

I don't know. Someone with more powerpc knowledge should take a look at
runtime/stack-ppc.c to see if that is always enough on ppc, or that you
need a real dwarf unwinder to have accurate backtraces on that
architecture.

> 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

Thanks,

Mark