dtrace discuss - Feb 2008 - How to save ustack result into a map, or pass it to another program

Hi,
   I want to save the stack information when memory is allocated using following
script, but it doesn''t work. Could anyone help me with it ?

#########
pid$1::malloc_internal:return,
pid$1::oversize:entry
/self->size/
{
   allocateMem[arg1] = ustack(10);   /* save relationship <address, stack>
*/
   self->size = 0;
}

I also tried invoking another command to save ustack, using following scripte
but also fail.

#########
pid$1::malloc_internal:return,
pid$1::oversize:entry
/self->size/
{
   system(saveStack(arg1, ustack(10)));  /* invoke another command to save
stack*/
   self->size = 0;
}

Here saveSatck is an executable program, it save "arg1" and
"stack" in a map.

I don''t want to print out result of ustack on screen, because the
output is very large after long time running.


BR
Jian Li


--
This message posted from opensolaris.org

> I want to save the stack information when memory is allocated using
> following script, but it doesn''t work. Could anyone help me with
it ?
> #########
> pid$1::malloc_internal:return,
> pid$1::oversize:entry
> /self->size/
> {
>    allocateMem[arg1] = ustack(10);   /* save relationship <address,
stack> */
>    self->size = 0;
> }
Wouldn''t be enough to just
...
{
	trace(arg1);
	ustack(10);
}

and redirect the output to a file? I don''t believe that you can assign
ustack''s output to any internal variable.

Other possibility would be to use
...
{
	@[arg1,ustack(10)]=count();
}

This would run until you press Ctrl-c, and then print out all
combinations of arg1,ustack(10) tuple, with the count of how many times
this combination happened.

I''m not sure if I can describe it well, here is example:

=======================================================================dtrace -n
''*write:return{@[arg1,stack()]=count()}''
...
Ctrl+C

...
                1
              genunix`write32+0x1e
 stackC       genunix`dtrace_systrace_syscall32+0x119
              unix`sys_syscall32+0x101
               50
                0
              genunix`write+0x2af
              genunix`write32+0x1e
 stackB       genunix`dtrace_systrace_syscall32+0x119
              unix`sys_syscall32+0x101
               57
                0
              genunix`fop_write+0x69
              genunix`write+0x2af
 stackA       genunix`write32+0x1e
              genunix`dtrace_systrace_syscall32+0x119
              unix`sys_syscall32+0x101
               57
=======================================================================I added
the stackA,B,C notes to this output.

If you read the result from the bottom upwards, you will see that write
was called from stackA and returned 0 57times. write was called using
call path stackB and returned 0 57times. etc ...


> I also tried invoking another command to save ustack, using following
scripte but also fail.
> 
> #########
> pid$1::malloc_internal:return,
> pid$1::oversize:entry
> /self->size/
> {
>    system(saveStack(arg1, ustack(10)));  /* invoke another command to save
stack*/
>    self->size = 0;
> }
You can''t run external programs like that. You have to use system(...).
Look at
http://wikis.sun.com/display/DTrace/Actions+and+Subroutines#ActionsandSubroutines-%7B%7Bsystem%7D%7D

> Here saveSatck is an executable program, it save "arg1" and
"stack" in a map.
I''m afraid that you can''t pass ustack() output as an argument
either.

> I don''t want to print out result of ustack on screen, because the
output is very large after long time running.
Redirect it to file, or use ''-o'' command line switch (be aware
that
''-o file'' does not overwrite original file, but rather appends
to it).

As a side note, maybe there are better tools for what you are tyring to
achieve? For hunting problems with memory Solaris has libumem.

man umem_debug

But that''s outside of the scope of this list, I''m afraid.

-- 
	Vlad
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 193 bytes
Desc: not available
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20080222/b6bd4fa1/attachment.bin>

ustack probably works by building a list of instruction pointers which
are later turned into a pretty string which makes this tricky enough
that I''m not surprised it doesn''t work.  That said it would be
sweet if
it did work by just storing the raw internal ustack representation
somehow and allowing it to be optionally traced later.

Some cool use cases malloc/free history, leak diagnostics.  I used
ustack to implement a ref counting history mechanism that required
setting a huge buffer size and using grep to dig the info I wanted out
of massive logs of ustack traces.   Basically I wanted to find errant
add/dec ref operations by logging each one and at some point in the
program''s execution the ref count goes bad and at that point I want to
trace the ref history for just that object.   Looking at the ustacks of
the add/dec ref operations makes fixing these types of problems trivial.
If dtrace let me maintain a data structure of ustacks''s keyed by some
value that I could later selectively trace that would have been sweet.
Sounds like I''m not the only one who could use that.
> -----Original Message-----
> From: dtrace-discuss-bounces at opensolaris.org 
> [mailto:dtrace-discuss-bounces at opensolaris.org] On Behalf Of 
> Vladimir Marek
> Sent: Friday, February 22, 2008 8:42 AM
> To: LiJIan
> Cc: dtrace-discuss at opensolaris.org
> Subject: Re: [dtrace-discuss] How to save ustack result into 
> a map, or pass it to another program
> 
> > I want to save the stack information when memory is allocated using 
> > following script, but it doesn''t work. Could anyone help me 
> with it ?
> 
> > #########
> > pid$1::malloc_internal:return,
> > pid$1::oversize:entry
> > /self->size/
> > {
> >    allocateMem[arg1] = ustack(10);   /* save relationship 
> <address, stack> */
> >    self->size = 0;
> > }
> 
> Wouldn''t be enough to just
> ...
> {
> 	trace(arg1);
> 	ustack(10);
> }
> 
> and redirect the output to a file? I don''t believe that you 
> can assign ustack''s output to any internal variable.
> 
> Other possibility would be to use
> ...
> {
> 	@[arg1,ustack(10)]=count();
> }
> 
> This would run until you press Ctrl-c, and then print out all 
> combinations of arg1,ustack(10) tuple, with the count of how 
> many times this combination happened.
> 
> I''m not sure if I can describe it well, here is example:
> 
> =============================================================>
=========> dtrace -n
''*write:return{@[arg1,stack()]=count()}''
> ...
> Ctrl+C
> 
> ...
>                 1
>               genunix`write32+0x1e
>  stackC       genunix`dtrace_systrace_syscall32+0x119
>               unix`sys_syscall32+0x101
>                50
>                 0
>               genunix`write+0x2af
>               genunix`write32+0x1e
>  stackB       genunix`dtrace_systrace_syscall32+0x119
>               unix`sys_syscall32+0x101
>                57
>                 0
>               genunix`fop_write+0x69
>               genunix`write+0x2af
>  stackA       genunix`write32+0x1e
>               genunix`dtrace_systrace_syscall32+0x119
>               unix`sys_syscall32+0x101
>                57
> =============================================================>
=========> I added the stackA,B,C notes to this output.
> 
> If you read the result from the bottom upwards, you will see 
> that write was called from stackA and returned 0 57times. 
> write was called using call path stackB and returned 0 
> 57times. etc ...
> 
> 
> 
> > I also tried invoking another command to save ustack, using 
> following scripte but also fail.
> > 
> > #########
> > pid$1::malloc_internal:return,
> > pid$1::oversize:entry
> > /self->size/
> > {
> >    system(saveStack(arg1, ustack(10)));  /* invoke another 
> command to save stack*/
> >    self->size = 0;
> > }
> 
> You can''t run external programs like that. You have to use 
> system(...).
> Look at
> http://wikis.sun.com/display/DTrace/Actions+and+Subroutines#Ac
> tionsandSubroutines-%7B%7Bsystem%7D%7D
> 
> 
> > Here saveSatck is an executable program, it save "arg1" and 
> "stack" in a map.
> 
> I''m afraid that you can''t pass ustack() output as an
argument either.
> 
> 
> > I don''t want to print out result of ustack on screen, 
> because the output is very large after long time running.
> 
> Redirect it to file, or use ''-o'' command line switch (be 
> aware that ''-o file'' does not overwrite original file,
but
> rather appends to it).
> 
> As a side note, maybe there are better tools for what you are 
> tyring to achieve? For hunting problems with memory Solaris 
> has libumem.
> 
> man umem_debug
> 
> But that''s outside of the scope of this list, I''m afraid.
> 
> -- 
> 	Vlad
>

I have tried using umem (First set some environment variables, then run the
program,  then "gcore pid_of_program", then "mdb gcore_xxx"
)  to detect memory leak with a simple test program, but it didn''t find
any memory leak but it should find.

I also found another issue when using umem. That is after the program runs for a
pretty long time,  then I use "gcore" to generate a core file, then I
use mdb to check the core file:  the result of "::umalog" seems only
show the recent memory operations information, those memory operations which
happened earlier were lost.

Come back to the original dtrace issue. I don''t want to use file system
or pipe ( in nature it use file system ? )  because in performance test, the
application has many many memory operations (malloc or free), and the D script
will output a big amount of information (ustack is big ).  This big amount
information need to be analyzed by another program (since D script itself cannot
save stack information keyed by some value e.g. returned address ).   The
analysis program store the memory allocation infomation <returned address,
stack>,  when free() is called the corresponding information is deleted. When
application terminates, the leaked memory information is saved in the analysis
program.

So the critical issue is how to efficiently pass the output data from the D
script to the analysis program.


--
This message posted from opensolaris.org

Hi Thomas,

That''s absolutely correct. ustack() is an action() which records data
to
trace buffer. A long-standing RFE is to treat it like some more easily
manipulated object, but that hasn''t really gained any momentum.

Adam

On Feb 22, 2008, at 11:23 AM, Thomas Reilly wrote:
>
> ustack probably works by building a list of instruction pointers which
> are later turned into a pretty string which makes this tricky enough
> that I''m not surprised it doesn''t work.  That said it
would be sweet
> if
> it did work by just storing the raw internal ustack representation
> somehow and allowing it to be optionally traced later.
>
> Some cool use cases malloc/free history, leak diagnostics.  I used
> ustack to implement a ref counting history mechanism that required
> setting a huge buffer size and using grep to dig the info I wanted out
> of massive logs of ustack traces.   Basically I wanted to find errant
> add/dec ref operations by logging each one and at some point in the
> program''s execution the ref count goes bad and at that point I
want to
> trace the ref history for just that object.   Looking at the ustacks  
> of
> the add/dec ref operations makes fixing these types of problems  
> trivial.
> If dtrace let me maintain a data structure of ustacks''s keyed by
some
> value that I could later selectively trace that would have been sweet.
> Sounds like I''m not the only one who could use that.
>
>> -----Original Message-----
>> From: dtrace-discuss-bounces at opensolaris.org
>> [mailto:dtrace-discuss-bounces at opensolaris.org] On Behalf Of
>> Vladimir Marek
>> Sent: Friday, February 22, 2008 8:42 AM
>> To: LiJIan
>> Cc: dtrace-discuss at opensolaris.org
>> Subject: Re: [dtrace-discuss] How to save ustack result into
>> a map, or pass it to another program
>>
>>> I want to save the stack information when memory is allocated using
>>> following script, but it doesn''t work. Could anyone help
me
>> with it ?
>>
>>> #########
>>> pid$1::malloc_internal:return,
>>> pid$1::oversize:entry
>>> /self->size/
>>> {
>>>   allocateMem[arg1] = ustack(10);   /* save relationship
>> <address, stack> */
>>>   self->size = 0;
>>> }
>>
>> Wouldn''t be enough to just
>> ...
>> {
>> 	trace(arg1);
>> 	ustack(10);
>> }
>>
>> and redirect the output to a file? I don''t believe that you
>> can assign ustack''s output to any internal variable.
>>
>> Other possibility would be to use
>> ...
>> {
>> 	@[arg1,ustack(10)]=count();
>> }
>>
>> This would run until you press Ctrl-c, and then print out all
>> combinations of arg1,ustack(10) tuple, with the count of how
>> many times this combination happened.
>>
>> I''m not sure if I can describe it well, here is example:
>>
>> =============================================================>>
=========>> dtrace -n
''*write:return{@[arg1,stack()]=count()}''
>> ...
>> Ctrl+C
>>
>> ...
>>                1
>>              genunix`write32+0x1e
>> stackC       genunix`dtrace_systrace_syscall32+0x119
>>              unix`sys_syscall32+0x101
>>               50
>>                0
>>              genunix`write+0x2af
>>              genunix`write32+0x1e
>> stackB       genunix`dtrace_systrace_syscall32+0x119
>>              unix`sys_syscall32+0x101
>>               57
>>                0
>>              genunix`fop_write+0x69
>>              genunix`write+0x2af
>> stackA       genunix`write32+0x1e
>>              genunix`dtrace_systrace_syscall32+0x119
>>              unix`sys_syscall32+0x101
>>               57
>> =============================================================>>
=========>> I added the stackA,B,C notes to this output.
>>
>> If you read the result from the bottom upwards, you will see
>> that write was called from stackA and returned 0 57times.
>> write was called using call path stackB and returned 0
>> 57times. etc ...
>>
>>
>>
>>> I also tried invoking another command to save ustack, using
>> following scripte but also fail.
>>>
>>> #########
>>> pid$1::malloc_internal:return,
>>> pid$1::oversize:entry
>>> /self->size/
>>> {
>>>   system(saveStack(arg1, ustack(10)));  /* invoke another
>> command to save stack*/
>>>   self->size = 0;
>>> }
>>
>> You can''t run external programs like that. You have to use
>> system(...).
>> Look at
>> http://wikis.sun.com/display/DTrace/Actions+and+Subroutines#Ac
>> tionsandSubroutines-%7B%7Bsystem%7D%7D
>>
>>
>>> Here saveSatck is an executable program, it save "arg1"
and
>> "stack" in a map.
>>
>> I''m afraid that you can''t pass ustack() output as an
argument either.
>>
>>
>>> I don''t want to print out result of ustack on screen,
>> because the output is very large after long time running.
>>
>> Redirect it to file, or use ''-o'' command line switch
(be
>> aware that ''-o file'' does not overwrite original
file, but
>> rather appends to it).
>>
>> As a side note, maybe there are better tools for what you are
>> tyring to achieve? For hunting problems with memory Solaris
>> has libumem.
>>
>> man umem_debug
>>
>> But that''s outside of the scope of this list, I''m
afraid.
>>
>> -- 
>> 	Vlad
>>
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org

--
Adam Leventhal, Fishworks                        http://blogs.sun.com/ahl

> I have tried using umem (First set some environment variables, then
> run the program,  then "gcore pid_of_program", then "mdb
gcore_xxx" )
> to detect memory leak with a simple test program, but it didn''t
find
> any memory leak but it should find. 
This does not sound right, but it''s outside of the scope of this
thread.
I am curious, if you want send me the source privately.

> Come back to the original dtrace issue. I don''t want to use file
> system or pipe ( in nature it use file system ? )  because in
> performance test, the application has many many memory operations
> (malloc or free), and the D script will output a big amount of
> information (ustack is big ).
I found in some situations that using gzip on dtrace output let me
collect huge amount of data quickly.

dtrace -n '' ... '' | gzip -c > file


> This big amount information need to be analyzed by another program
> (since D script itself cannot save stack information keyed by some
> value e.g. returned address ).   The analysis program store the memory
> allocation infomation <returned address, stack>,  when free() is
> called the corresponding information is deleted. When application
> terminates, the leaked memory information is saved in the analysis
> program.
I would still try to use another solution, for example valgrind is
excellent tool (actually I''m not sure how excellent it is on Solaris,
but on Linux it works more then well).
> So the critical issue is how to efficiently pass the output data from
> the D script to the analysis program.
You could also use drace | gzip -c > /tmp/file, where /tmp is ramdisk.

That''s what just crossed my mind, I hope it helps.

-- 
	Vlad
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 193 bytes
Desc: not available
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20080225/5c828aeb/attachment.bin>