Qihua Wu
2009-May-04 01:58 UTC
[dtrace-discuss] output of ustack only shows the library call but no program call which called the library
After I run dtrace -n ''syscall::brk:entry {ustack()}'', I found
some output
show the function from ONLY library. But libaray is not runnable by itself.
0 59753 brk:entry
libc.so.1`_brk_unlocked+0xa
libc.so.1`sbrk+0x20
libc.so.1`_morecore+0x12b
libc.so.1`_malloc_unlocked+0x10d
libc.so.1`malloc+0x2d
libproc.so.1`optimize_symtab+0x6c
libproc.so.1`Pbuild_file_symtab+0x787
libproc.so.1`build_map_symtab+0x36
libproc.so.1`Pxlookup_by_name+0x6d
libproc.so.1`Plookup_by_name+0x1c
libproc.so.1`ps_pglobal_lookup+0x1a
librtld_db.so.1`_rd_reset64+0x10f
librtld_db.so.1`rd_reset+0x58
librtld_db.so.1`rd_new+0x6d
libproc.so.1`Prd_agent+0x4f
libproc.so.1`Pxlookup_by_addr+0x55
libproc.so.1`Plookup_by_addr+0xc
libdtrace.so.1`dt_print_ustack+0x16b
libdtrace.so.1`dt_consume_cpu+0x3ae
libdtrace.so.1`dt_consume_begin+0x92
===> The library is not runnable by itself, why the function comes from
library?
0 59753 brk:entry
libc.so.1`_brk_unlocked+0xa
libc.so.1`sbrk+0x20
libc.so.1`_morecore+0x27
libc.so.1`_malloc_unlocked+0x10d
libc.so.1`malloc+0x2d
libproc.so.1`optimize_symtab+0x6c
libproc.so.1`Pbuild_file_symtab+0x787
libproc.so.1`build_map_symtab+0x36
libproc.so.1`Pxlookup_by_addr+0x70
libproc.so.1`Plookup_by_addr+0xc
libdtrace.so.1`dt_print_ustack+0x16b
libdtrace.so.1`dt_consume_cpu+0x3ae
libdtrace.so.1`dt_consume_begin+0x92
libdtrace.so.1`dtrace_consume+0x114
libdtrace.so.1`dtrace_work+0xaa
dtrace`main+0x902
dtrace`_start+0x6c ==> This
one is better to understand: dtrace is a process calling some library, so
it makes sense to have the "dtrace`_start+0x6c" as the outer most
function.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20090504/0f7ca4db/attachment.html>
Zhu, Lejun
2009-May-04 02:10 UTC
[dtrace-discuss] output of ustack only shows the library call but no program call which called the library
Try increase "ustackframes", I think the default is 20 and you
won''t see the real entry point when ustack is too deep.
________________________________
From: dtrace-discuss-bounces at opensolaris.org [mailto:dtrace-discuss-bounces
at opensolaris.org] On Behalf Of Qihua Wu
Sent: 2009?5?4? 9:59
To: dtrace-discuss at opensolaris.org
Subject: [dtrace-discuss] output of ustack only shows the library call but no
program call which called the library
After I run dtrace -n ''syscall::brk:entry {ustack()}'', I found
some output show the function from ONLY library. But libaray is not runnable by
itself.
0 59753 brk:entry
libc.so.1`_brk_unlocked+0xa
libc.so.1`sbrk+0x20
libc.so.1`_morecore+0x12b
libc.so.1`_malloc_unlocked+0x10d
libc.so.1`malloc+0x2d
libproc.so.1`optimize_symtab+0x6c
libproc.so.1`Pbuild_file_symtab+0x787
libproc.so.1`build_map_symtab+0x36
libproc.so.1`Pxlookup_by_name+0x6d
libproc.so.1`Plookup_by_name+0x1c
libproc.so.1`ps_pglobal_lookup+0x1a
librtld_db.so.1`_rd_reset64+0x10f
librtld_db.so.1`rd_reset+0x58
librtld_db.so.1`rd_new+0x6d
libproc.so.1`Prd_agent+0x4f
libproc.so.1`Pxlookup_by_addr+0x55
libproc.so.1`Plookup_by_addr+0xc
libdtrace.so.1`dt_print_ustack+0x16b
libdtrace.so.1`dt_consume_cpu+0x3ae
libdtrace.so.1`dt_consume_begin+0x92 ===>
The library is not runnable by itself, why the function comes from library?
0 59753 brk:entry
libc.so.1`_brk_unlocked+0xa
libc.so.1`sbrk+0x20
libc.so.1`_morecore+0x27
libc.so.1`_malloc_unlocked+0x10d
libc.so.1`malloc+0x2d
libproc.so.1`optimize_symtab+0x6c
libproc.so.1`Pbuild_file_symtab+0x787
libproc.so.1`build_map_symtab+0x36
libproc.so.1`Pxlookup_by_addr+0x70
libproc.so.1`Plookup_by_addr+0xc
libdtrace.so.1`dt_print_ustack+0x16b
libdtrace.so.1`dt_consume_cpu+0x3ae
libdtrace.so.1`dt_consume_begin+0x92
libdtrace.so.1`dtrace_consume+0x114
libdtrace.so.1`dtrace_work+0xaa
dtrace`main+0x902
dtrace`_start+0x6c
==> This one is better to understand: dtrace is a process calling some
library, so it makes sense to have the "dtrace`_start+0x6c" as the
outer most function.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20090504/f4fddcca/attachment.html>
Qihua Wu
2009-May-04 03:37 UTC
[dtrace-discuss] output of ustack only shows the library call but no program call which called the library
Thanks lejun.
For the following output, the first called function (the last function show
in ustack) is still not from a process (in this case mysqld).
dtrace -n ''syscall::portfs:entry {ustack();}''
11 60041 portfs:entry
libc.so.1`_portfs+0xa
mysqld`_Z25ep_start_waiting_for_dataP12EP_FILE_INFO+0x55
mysqld`ep_thread_proc+0x194 *====> function of
mysqld is in the middle of th ustack*
libc.so.1`_thr_setup+0x5b
libc.so.1`_lwp_start *===> this
library call is the first call, but who called this function, should a call
always started from function main()?*
11 60041 portfs:entry
libc.so.1`_portfs+0xa
mysqld`ep_thread_proc+0x81
libc.so.1`_thr_setup+0x5b
libc.so.1`_lwp_start
11 60041 portfs:entry
libc.so.1`_portfs+0xa
mysqld`_Z25ep_start_waiting_for_dataP12EP_FILE_INFO+0x55
mysqld`ep_thread_proc+0x194
libc.so.1`_thr_setup+0x5b
libc.so.1`_lwp_start
11 60041 portfs:entry
libc.so.1`_portfs+0xa
mysqld`ep_thread_proc+0x81
libc.so.1`_thr_setup+0x5b
libc.so.1`_lwp_start
11 60041 portfs:entry
libc.so.1`_portfs+0xa
mysqld`_Z25ep_start_waiting_for_dataP12EP_FILE_INFO+0x55
mysqld`ep_thread_proc+0x194
libc.so.1`_thr_setup+0x5b
libc.so.1`_lwp_start
2009/5/4 Zhu, Lejun <lejun.zhu at intel.com>
> Try increase "ustackframes", I think the default is 20 and you
won''t see
> the real entry point when ustack is too deep.
>
> ------------------------------
> *From:* dtrace-discuss-bounces at opensolaris.org [mailto:
> dtrace-discuss-bounces at opensolaris.org] *On Behalf Of *Qihua Wu
> *Sent:* 2009?5?4? 9:59
> *To:* dtrace-discuss at opensolaris.org
> *Subject:* [dtrace-discuss] output of ustack only shows the library call
> but no program call which called the library
>
> After I run dtrace -n ''syscall::brk:entry {ustack()}'', I
found some output
> show the function from ONLY library. But libaray is not runnable by itself.
>
>
> 0 59753 brk:entry
> libc.so.1`_brk_unlocked+0xa
> libc.so.1`sbrk+0x20
> libc.so.1`_morecore+0x12b
> libc.so.1`_malloc_unlocked+0x10d
> libc.so.1`malloc+0x2d
> libproc.so.1`optimize_symtab+0x6c
> libproc.so.1`Pbuild_file_symtab+0x787
> libproc.so.1`build_map_symtab+0x36
> libproc.so.1`Pxlookup_by_name+0x6d
> libproc.so.1`Plookup_by_name+0x1c
> libproc.so.1`ps_pglobal_lookup+0x1a
> librtld_db.so.1`_rd_reset64+0x10f
> librtld_db.so.1`rd_reset+0x58
> librtld_db.so.1`rd_new+0x6d
> libproc.so.1`Prd_agent+0x4f
> libproc.so.1`Pxlookup_by_addr+0x55
> libproc.so.1`Plookup_by_addr+0xc
> libdtrace.so.1`dt_print_ustack+0x16b
> libdtrace.so.1`dt_consume_cpu+0x3ae
> libdtrace.so.1`dt_consume_begin+0x92
> ===> The library is not runnable by itself, why the function comes from
> library?
>
> 0 59753 brk:entry
> libc.so.1`_brk_unlocked+0xa
> libc.so.1`sbrk+0x20
> libc.so.1`_morecore+0x27
> libc.so.1`_malloc_unlocked+0x10d
> libc.so.1`malloc+0x2d
> libproc.so.1`optimize_symtab+0x6c
> libproc.so.1`Pbuild_file_symtab+0x787
> libproc.so.1`build_map_symtab+0x36
> libproc.so.1`Pxlookup_by_addr+0x70
> libproc.so.1`Plookup_by_addr+0xc
> libdtrace.so.1`dt_print_ustack+0x16b
> libdtrace.so.1`dt_consume_cpu+0x3ae
> libdtrace.so.1`dt_consume_begin+0x92
> libdtrace.so.1`dtrace_consume+0x114
> libdtrace.so.1`dtrace_work+0xaa
> dtrace`main+0x902
>
> dtrace`_start+0x6c ==>
This
> one is better to understand: dtrace is a process calling some library, so
> it makes sense to have the "dtrace`_start+0x6c" as the outer most
function.
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20090504/00cdb5f9/attachment.html>
Rayson Ho
2009-May-04 03:55 UTC
[dtrace-discuss] output of ustack only shows the library call but no program call which called the library
MySQL is a multi-threaded process, so what you are seeing is normal. When DTrace is looking at the stack of a slave thread, it won''t be able to show you the call frame of main() because each thread has its own stack. BTW, what are you trying to trace?? There are already a number of probes in MySQL. Rayson On 5/3/09, Qihua Wu <dtrace.wu at gmail.com> wrote:> Thanks lejun. > > For the following output, the first called function (the last function show > in ustack) is still not from a process (in this case mysqld). > > dtrace -n ''syscall::portfs:entry {ustack();}'' > > 11 60041 portfs:entry > libc.so.1`_portfs+0xa > > mysqld`_Z25ep_start_waiting_for_dataP12EP_FILE_INFO+0x55 > mysqld`ep_thread_proc+0x194 ====> > function of mysqld is in the middle of th ustack > libc.so.1`_thr_setup+0x5b > libc.so.1`_lwp_start > ===> this library call is the first call, but who called this function, > should a call always started from function main()? > > 11 60041 portfs:entry > libc.so.1`_portfs+0xa > mysqld`ep_thread_proc+0x81 > libc.so.1`_thr_setup+0x5b > libc.so.1`_lwp_start > > 11 60041 portfs:entry > libc.so.1`_portfs+0xa > > mysqld`_Z25ep_start_waiting_for_dataP12EP_FILE_INFO+0x55 > mysqld`ep_thread_proc+0x194 > libc.so.1`_thr_setup+0x5b > libc.so.1`_lwp_start > > 11 60041 portfs:entry > libc.so.1`_portfs+0xa > mysqld`ep_thread_proc+0x81 > libc.so.1`_thr_setup+0x5b > libc.so.1`_lwp_start > > 11 60041 portfs:entry > libc.so.1`_portfs+0xa > > mysqld`_Z25ep_start_waiting_for_dataP12EP_FILE_INFO+0x55 > mysqld`ep_thread_proc+0x194 > libc.so.1`_thr_setup+0x5b > libc.so.1`_lwp_start > > > > 2009/5/4 Zhu, Lejun <lejun.zhu at intel.com> > > > > > > > Try increase "ustackframes", I think the default is 20 and you won''t see > the real entry point when ustack is too deep. > > > > ________________________________ > From: dtrace-discuss-bounces at opensolaris.org > [mailto:dtrace-discuss-bounces at opensolaris.org] On Behalf > Of Qihua Wu > > Sent: 2009?5?4? 9:59 > > To: dtrace-discuss at opensolaris.org > > Subject: [dtrace-discuss] output of ustack only shows the library call but > no program call which called the library > > > > > > > > > > > > After I run dtrace -n ''syscall::brk:entry {ustack()}'', I found some output > show the function from ONLY library. But libaray is not runnable by itself. > > > > > > 0 59753 brk:entry > > libc.so.1`_brk_unlocked+0xa > > libc.so.1`sbrk+0x20 > > libc.so.1`_morecore+0x12b > > libc.so.1`_malloc_unlocked+0x10d > > libc.so.1`malloc+0x2d > > libproc.so.1`optimize_symtab+0x6c > > libproc.so.1`Pbuild_file_symtab+0x787 > > libproc.so.1`build_map_symtab+0x36 > > libproc.so.1`Pxlookup_by_name+0x6d > > libproc.so.1`Plookup_by_name+0x1c > > libproc.so.1`ps_pglobal_lookup+0x1a > > librtld_db.so.1`_rd_reset64+0x10f > > librtld_db.so.1`rd_reset+0x58 > > librtld_db.so.1`rd_new+0x6d > > libproc.so.1`Prd_agent+0x4f > > libproc.so.1`Pxlookup_by_addr+0x55 > > libproc.so.1`Plookup_by_addr+0xc > > libdtrace.so.1`dt_print_ustack+0x16b > > libdtrace.so.1`dt_consume_cpu+0x3ae > > libdtrace.so.1`dt_consume_begin+0x92 > ===> The library is not runnable by itself, > why the function comes from library? > > > > 0 59753 brk:entry > > libc.so.1`_brk_unlocked+0xa > > libc.so.1`sbrk+0x20 > > libc.so.1`_morecore+0x27 > > libc.so.1`_malloc_unlocked+0x10d > > libc.so.1`malloc+0x2d > > libproc.so.1`optimize_symtab+0x6c > > libproc.so.1`Pbuild_file_symtab+0x787 > > libproc.so.1`build_map_symtab+0x36 > > libproc.so.1`Pxlookup_by_addr+0x70 > > libproc.so.1`Plookup_by_addr+0xc > > libdtrace.so.1`dt_print_ustack+0x16b > > libdtrace.so.1`dt_consume_cpu+0x3ae > > libdtrace.so.1`dt_consume_begin+0x92 > > libdtrace.so.1`dtrace_consume+0x114 > > libdtrace.so.1`dtrace_work+0xaa > > dtrace`main+0x902 > > dtrace`_start+0x6c > ==> This one is better to > understand: dtrace is a process calling some library, so it makes sense to > have the "dtrace`_start+0x6c" as the outer most function. > > > > > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org >