thr3ads.net - dtrace discuss - [dtrace-discuss] synchronize output of probes and traced process [Nov 2005]

If this information is useful, please help other people find it:
Share via:

Christian Klutz

2005-Nov-02 11:51 UTC

[dtrace-discuss] synchronize output of probes and traced process

Hi,

I''m currently toying around with adding probes to TCL.  Now
I''m not really an expert in TCL''s internal implementation,
especially not the byte code compiler and all that, but I think I managed to put
the probes for "cmd-entry" and "cmd-return" at the right
location.  At least if I put simple "printf" statements at the
respective locations all seems work nicely.

When I do add some SDT probes instead of the printf statements, and run dtrace
like this:

$ /usr/sbin/dtrace -s test.d -c "tclsh foo.tcl"

The output of the foo.tcl script comes first, then all the probes that I have
setup (for a dump of the actual output please refer to the attached test.txt
file).

OK, now to the actual question: isn''t the output of the traced process
(at least as long as it has been started by dtrace - "-c" option)
synchronized with the output the probes generate (at least using a C example
they seem to be)?

Maybe it is something particular to TCL that causes this behaviour, but frankly
before digging into it deeper I''d like to rule out the possibility that
this is actually the way it is with dtrace :-)

Thanks,
Christian
This message posted from opensolaris.org
-------------- next part --------------
A non-text attachment was scrubbed...
Name: foo.tcl
Type: application/x-tcl
Size: 71 bytes
Desc: not available
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20051102/6ada1845/attachment.tcl>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: test.d
Type: application/octet-stream
Size: 272 bytes
Desc: not available
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20051102/6ada1845/attachment.obj>
-------------- next part --------------
SETUP....
RUNNING....
hi
 > if
 > info
 > info
 > proc
 > proc
 > if
 > tclInit
 > global
 > global
 > global
 > global
 > rename
 > rename
 > info
 > info
 > info
 > info
 > unset
 > unset
 > concat
 > concat
 > file
 > file
 > file
 > file
 > uplevel
  > source
   > if
    > info
    > info
   > if
   > package
   > package
   > if
    > info
    > info
    > info
    > info
   > if
   > namespace
    > variable
    > variable
    > info
    > info
    > info
    > info
    > info
    > info
    > file
    > file
    > list
    > list
    > foreach
     > lsearch
     > lsearch
     > lappend
     > lappend
     > lsearch
     > lsearch
     > lappend
     > lappend
    > foreach
    > info
    > info
    > file
    > file
    > file
    > file
    > file
    > file
    > lsearch
    > lsearch
    > lappend
    > lappend
    > info
    > info
    > foreach
     > lsearch
     > lsearch
    > foreach
   > namespace
   > if
    > interp
    > interp
   > if
   > package
   > package
   > if
    > interp
    > interp
   > if
   > if
    > info
    > info
   > if
   > set
   > set
   > set
   > set
   > if
    > info
    > info
    > proc
    > proc
   > if
   > proc
   > proc
   > proc
   > proc
   > proc
   > proc
   > proc
   > proc
   > proc
   > proc
   > if
    > proc
    > proc
   > if
   > proc
   > proc
  > source
 > uplevel
 > tclInit
 > puts
 > puts
 > proc
 > proc
 > puts
 > puts
 > foo
 > puts
 > puts
 > foo
 > exit

Adam Leventhal

2005-Nov-02 17:31 UTC

head link

[dtrace-discuss] synchronize output of probes and traced process

Hi Christian,
> OK, now to the actual question: isn''t the output of the traced
> process (at least as long as it has been started by dtrace - "-c"
> option) synchronized with the output the probes generate (at least
> using a C example they seem to be)?
I imagine you''re thinking of something like truss where you your
program
does something and you see truss reporting that synchronously. DTrace works
fairly differently; rather than stopping the process at every point of
interest, DTrace records traced data to an in-kernel buffer which is then
read out periodically by the user-land consumer. Which explains what
you''re
seeing.

If you really want synchronous output, you could do something like this:

my-probe
{
	printf("got to my probe");
	stop();
	system("prun %d", pid);
}

This will cause DTrace to act a bit like truss in that it will stop the
process each time it hits the probe of interest. The system action is
processed in the same data stream as the printf() or trace() actions.
Note that by default, the in-kernel buffer is captured only once per
second so you might need to crank up the switchrate (see the chapter in
the Solaris Dynamic Tracing Guide on options and tunables) as that will
meter the rate that the traced program executes.

Adam

On Wed, Nov 02, 2005 at 03:51:05AM -0800, Christian Klutz
wrote:> Hi,
> 
> I''m currently toying around with adding probes to TCL.  Now
I''m not really an expert in TCL''s internal implementation,
especially not the byte code compiler and all that, but I think I managed to put
the probes for "cmd-entry" and "cmd-return" at the right
location.  At least if I put simple "printf" statements at the
respective locations all seems work nicely.
> 
> When I do add some SDT probes instead of the printf statements, and run
dtrace like this:
> 
> $ /usr/sbin/dtrace -s test.d -c "tclsh foo.tcl"
> 
> The output of the foo.tcl script comes first, then all the probes that I
have setup (for a dump of the actual output please refer to the attached
test.txt file).
> 
> OK, now to the actual question: isn''t the output of the traced
process (at least as long as it has been started by dtrace - "-c"
option) synchronized with the output the probes generate (at least using a C
example they seem to be)?
> 
> Maybe it is something particular to TCL that causes this behaviour, but
frankly before digging into it deeper I''d like to rule out the
possibility that this is actually the way it is with dtrace :-)
> 
> Thanks,
> Christian
> This message posted from opensolaris.org
> SETUP....
> RUNNING....
> hi
>  > if
>  > info
>  > info
>  > proc
>  > proc
>  > if
>  > tclInit
>  > global
>  > global
>  > global
>  > global
>  > rename
>  > rename
>  > info
>  > info
>  > info
>  > info
>  > unset
>  > unset
>  > concat
>  > concat
>  > file
>  > file
>  > file
>  > file
>  > uplevel
>   > source
>    > if
>     > info
>     > info
>    > if
>    > package
>    > package
>    > if
>     > info
>     > info
>     > info
>     > info
>    > if
>    > namespace
>     > variable
>     > variable
>     > info
>     > info
>     > info
>     > info
>     > info
>     > info
>     > file
>     > file
>     > list
>     > list
>     > foreach
>      > lsearch
>      > lsearch
>      > lappend
>      > lappend
>      > lsearch
>      > lsearch
>      > lappend
>      > lappend
>     > foreach
>     > info
>     > info
>     > file
>     > file
>     > file
>     > file
>     > file
>     > file
>     > lsearch
>     > lsearch
>     > lappend
>     > lappend
>     > info
>     > info
>     > foreach
>      > lsearch
>      > lsearch
>     > foreach
>    > namespace
>    > if
>     > interp
>     > interp
>    > if
>    > package
>    > package
>    > if
>     > interp
>     > interp
>    > if
>    > if
>     > info
>     > info
>    > if
>    > set
>    > set
>    > set
>    > set
>    > if
>     > info
>     > info
>     > proc
>     > proc
>    > if
>    > proc
>    > proc
>    > proc
>    > proc
>    > proc
>    > proc
>    > proc
>    > proc
>    > proc
>    > proc
>    > if
>     > proc
>     > proc
>    > if
>    > proc
>    > proc
>   > source
>  > uplevel
>  > tclInit
>  > puts
>  > puts
>  > proc
>  > proc
>  > puts
>  > puts
>  > foo
>  > puts
>  > puts
>  > foo
>  > exit
> 
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org
-- 
Adam Leventhal, Solaris Kernel Development       http://blogs.sun.com/ahl

Christian Klutz

2005-Nov-03 06:08 UTC

head link

[dtrace-discuss] Re: synchronize output of probes and traced process

Hi Adam,
> > OK, now to the actual question: isn''t the output of
> the traced
> > process (at least as long as it has been started by
> dtrace - "-c"
> > option) synchronized with the output the probes
> generate (at least
> > using a C example they seem to be)?
> 
> I imagine you''re thinking of something like truss
> where you your program
> does something and you see truss reporting that
> synchronously. DTrace works
> fairly differently; rather than stopping the process
> at every point of
> interest, DTrace records traced data to an in-kernel
> buffer which is then
> read out periodically by the user-land consumer.
> Which explains what you''re
> seeing.
Thanks for clarifying this to me.  Actually I thought that it is that way, just
wanted to make sure that it is not some internal working of the TCL interpreter
that could cause that.
> 
> If you really want synchronous output, you could do
> something like this:
> 
> my-probe
> {
> 	printf("got to my probe");
> 	stop();
> 	system("prun %d", pid);
> }
> 
> This will cause DTrace to act a bit like truss in
> that it will stop the
> process each time it hits the probe of interest. The
> system action is
> processed in the same data stream as the printf() or
> trace() actions.
> Note that by default, the in-kernel buffer is
> captured only once per
> second 
Ah... that explains why the aforementioned "C sample" seemed to be
synchronous in output; it "artificially" slept 1 second after each
probe - duh! I should really read the documentation then :-)
> so you might need to crank up the switchrate
> (see the chapter in
> the Solaris Dynamic Tracing Guide on options and
> tunables) as that will
> meter the rate that the traced program executes.
I''ll give that a try, but if the default is the way it is,
it''s OK for me :-)
> 
[snip]> 
Thanks,
Christian
This message posted from opensolaris.org

dtrace discuss - Nov 2005 - synchronize output of probes and traced process

[dtrace-discuss] synchronize output of probes and traced process

[dtrace-discuss] synchronize output of probes and traced process

[dtrace-discuss] Re: synchronize output of probes and traced process