dtrace discuss - May 2007 - statistics for user thread in a user process.

Hi,
 
I need to calculate the execution time per thread in a user process. 

User thread means not LWP (created in kernel).                
proc:unix:lwp_rtt:lwp-start
/pid == $target/
{
self->start = timestamp; 
}
proc:genunix::lwp-exit
/self->start/
{
@total[tid, stringof(curpsinfo->pr_fname)] = sum(timestamp - self->start);
self->start = 0; /* clear the thread variable */
}
 
These probes giving me execution time taken by kernel thread. Some time output
was ''0''. May be because at that particular time, LWP is not
attached to any user thread.
 
So I thought of doing some thing like this....
pid$target:libpthread.so:pthread_create:entry
{
self->ts = timestamp;
}
pid$target:libpthread.so:pthread_exit:return
{
@thrTotTime[tid, stringof(curpsinfo->pr_fname)] = sum(timestamp -
self->ts);
}
But there is no probe defined for libpthread. Any idea what I need to calculate
execution time taken by a user thread (both in user mode and kernel mode).
Please correct me if I am wrong.
 
TIA
Vineet.
_________________________________________________________________
Add some color. Personalize your inbox with your favorite colors.
www.windowslive-hotmail.com/learnmore/personalize.html?locale=en-us&ocid=TXT_TAGLM_HMWL_reten_addcolor_0507
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20070516/7d791291/attachment.html>

In Solaris 10 (and Solaris 9, and Solaris 8 when linking libthread.so 
from /usr/lib/lwp)
a 1-to-1 thread model is implemented. All user threads have an LWP (and 
kernel thread).
Unbound threads no longer exist.

The easiest way to track this is with prstat:

#prstat -Lp <PID>

will provide a per-LWP (and thus per-thread) time.

A DTrace approach may be to use the sched provider, using on-cpu and 
off-cpu probes,
and a sum aggregation key''d on the thread ID:

#!/usr/sbin/dtrace -qs

sched:::on-cpu
/ pid == $target /
{
    self->st[tid] = timestamp;
}
sched:::off-cpu
/ pid == $target && self->st[tid] /
{
    @times = sum(timestamp - self->st[tid]);
    self->st[tid] = 0;
}

tick-10sec
{
    normalize(@times, 1000);
    printa(@times);
    trunc(@times);
}

The above will provide on-cpu time per thread for the past 10 seconds,
in microseconds.

Technically, now that I think about it, I should be using vtimestamp 
instead of timestamp,
but in my q&d test case (quick and dirty), it didn''t make an
appreciable
difference.

Note also that the actual pthread_XXXXX() APIs are now implemented in 
libc, not
libpthread.so (unified process model in Solaris 10).

/jim


Vineet Goel wrote:
> Hi,
>  
> I need to calculate the execution time per thread in a user process.
> User thread means not LWP (created in kernel).
>                proc:unix:lwp_rtt:lwp-start
> /pid == $target/
> {
> self->start = timestamp;
> }
> proc:genunix::lwp-exit
> /self->start/
> {
> @total[tid, stringof(curpsinfo->pr_fname)] = sum(timestamp -
self->start);
> self->start = 0; /* clear the thread variable */
> }
>  
> These probes giving me execution time taken by kernel thread. Some 
> time output was ''0''. May be because at that particular
time, LWP is
> not attached to any user thread.
>  
> So I thought of doing some thing like this....
> pid$target:libpthread.so:pthread_create:entry
> {
> self->ts = timestamp;
> }
> pid$target:libpthread.so:pthread_exit:return
> {
> @thrTotTime[tid, stringof(curpsinfo->pr_fname)] = sum(timestamp - 
> self->ts);
> }
> But there is no probe defined for libpthread.
> Any idea what I need to calculate execution time taken by a user 
> thread (both in user mode and kernel mode).
> Please correct me if I am wrong.
>  
> TIA
> Vineet.
>
> ------------------------------------------------------------------------
> Change is good. See what''s different about Windows Live Hotmail.
Check
> it out! 
>
<www.windowslive-hotmail.com/learnmore/default.html?locale=en-us&ocid=RMT_TAGLM_HMWL_reten_changegood_0507>
>
> ------------------------------------------------------------------------
>
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org
>

BUG ALERT

>
>    @times = sum(timestamp - self->st[tid]);
This should be:

@times[tid] = sum(timestamp - self->st[tid]);

Sorry,
/jim

Jim Mauro wrote:
> 
> The easiest way to track this is with prstat:
> 
> #prstat -Lp <PID>
Thanks, I can use this info.
> A DTrace approach may be to use the sched provider, using on-cpu and 
> off-cpu probes,
> and a sum aggregation key''d on the thread ID:
This seems to be just what I need.  Yesterday I posted "getting a process
frequency and percent time on CPU" and the answer was to try these probes.
With a little tinkering I came up with a script similar to yours.
> sched:::on-cpu
> / pid == $target /
> {
>    self->st[tid] = timestamp;
I read about the use of self-> and attempted to use that in my script but
I still got strange results that suggested overlap.  I think I may have
that fixed but there is something I don''t understand.  If tid is thread
ID, then isn''t it enough to have st[tid] without needing self->?  If
I
am wrong, can you explain why?


When I included the self-> in my script, I get times that overlap

TIME ON          TIME OFF         DELTA TIME          TID  CPU
              338              536              303     38    0
              578             1007              240     38    0
              673              747              634     37    0
              758             1208               85     37    0
             1047             1178              469     38    0
             1217             1326              170     38    0


When I removed the self-> so I have just on[tid] the times still
overlap.

TIME ON          TIME OFF         DELTA TIME          TID  CPU
              197              499               18     41    0
              538              730              341     41    0
              665              729              635     40    0
              740             1206               75     40    0
              814             1245              276     41    0
             1255             1414              441     41    0

So, it seems it doesn''t make any difference in my script with or
without
self->.  I am confused.  Can anyone shed some light on this?


#!/usr/sbin/dtrace -s

#pragma D option quiet

dtrace:::BEGIN
{
    printf("\n%-16s %-16s %-16s %6s %4s\n", "TIME ON",
"TIME OFF", "DELTA TIME", "TID", "CPU");
    lasttime[tid] = vtimestamp/1000;
}

sched:::on-cpu
/pid == $1/
{
    on[tid] = vtimestamp/1000;
}

sched:::off-cpu
/pid == $1 && on[tid]/
{
    @time[on[tid], vtimestamp/1000, on[tid] - lasttime[tid], tid, cpu] =
count();
    lasttime[tid] = on[tid];
    on[tid] = 0;
}

dtrace:::END
{
    printa("%16d %16d %16d %6d %4d\n", @time);
    trunc(@time);
}

Damon Register

Hi Jim,

On 5/17/07, Jim Mauro <James.Mauro at sun.com>
wrote:
> ...
> A DTrace approach may be to use the sched provider, using on-cpu and
> off-cpu probes,
> and a sum aggregation key''d on the thread ID:
>
> #!/usr/sbin/dtrace -qs
>
> sched:::on-cpu
> / pid == $target /
> {
>     self->st[tid] = timestamp;
Is there any reason why you are using self->st[tid] instead of
self->st since self already identifies the thread?
> }
> sched:::off-cpu
> / pid == $target && self->st[tid] /
> {
>     @times = sum(timestamp - self->st[tid]);
>     self->st[tid] = 0;
> }
>
> tick-10sec
> {
>     normalize(@times, 1000);
>     printa(@times);
>     trunc(@times);
> }
-- 
Just me,
Wire ...
Blog: <prstat.blogspot.com>

Actually, just force of habit.

Just using self->st provides the same behavior (at least it
did in my test case).

Thanks,
/jim
>
> Is there any reason why you are using self->st[tid] instead of
> self->st since self already identifies the thread?

> I read about the use of self-> and attempted to use that in my script
but
> I still got strange results that suggested overlap.  I think I may have
> that fixed but there is something I don''t understand.  If tid is
thread
> ID, then isn''t it enough to have st[tid] without needing
self->?  If I
> am wrong, can you explain why?
Good question, and I really should defer to someone that understands the
variable scope in DTrace better than me (but that won''t stop me from
putting my foot in my mouth ... :^).

The use of "self->st[tid]" versus "st[tid]" alters the
scope of the
variable.
"self->" creates a thread-local variable, versus
"st[tid]", which defines
a global variable. Variable scope is actually covered very well in the
Solaris Dynamic Tracing Guide, and you can reference this:

http://www.opensolaris.org/jive/thread.jspa?messageID=67338&#67338

for more on global variables.

In the case of my test script, I''m using a predicate ( / pid == $target
/ )
and running DTrace on a target process. So the probes firing from other
threads going on and off cpu will not alter my data, since the action will
not be taken as a result of the predicate evaluating false. It is for this
reason I believe the use of a global or thread local variable yields the 
same
result.

HTH,
/jim

On 5/17/07, Damon Register <damon.w.register at lmco.com>
wrote:
> This seems to be just what I need.  Yesterday I posted "getting a
process
> frequency and percent time on CPU" and the answer was to try these
probes.
> With a little tinkering I came up with a script similar to yours.
>
> > sched:::on-cpu
> > / pid == $target /
> > {
> >    self->st[tid] = timestamp;
> I read about the use of self-> and attempted to use that in my script
but
> I still got strange results that suggested overlap.  I think I may have
> that fixed but there is something I don''t understand.  If tid is
thread
> ID, then isn''t it enough to have st[tid] without needing
self->?  If I
> am wrong, can you explain why?
>
> When I included the self-> in my script, I get times that overlap
>
> TIME ON          TIME OFF         DELTA TIME          TID  CPU
>               338              536              303     38    0
>               578             1007              240     38    0
>               673              747              634     37    0
>               758             1208               85     37    0
>              1047             1178              469     38    0
>              1217             1326              170     38    0
vtimestamp is not appropriate for "Time on".  vtimestamp should only
make sense within the current thread and your overlaps occurs when the
CPU switches to a different thread.  You want timestamp instead.
> When I removed the self-> so I have just on[tid] the times still
> overlap.
>
> TIME ON          TIME OFF         DELTA TIME          TID  CPU
>               197              499               18     41    0
>               538              730              341     41    0
>               665              729              635     40    0
>               740             1206               75     40    0
>               814             1245              276     41    0
>              1255             1414              441     41    0
>
> So, it seems it doesn''t make any difference in my script with or
without
> self->.  I am confused.  Can anyone shed some light on this?
> #!/usr/sbin/dtrace -s
>
> #pragma D option quiet
>
> dtrace:::BEGIN
> {
>     printf("\n%-16s %-16s %-16s %6s %4s\n", "TIME ON",
"TIME OFF", "DELTA TIME", "TID", "CPU");
>     lasttime[tid] = vtimestamp/1000;
lasttime[tid] does not make any sense here since BEGIN probe fires
under the context of dtrace(1M).
> }
> sched:::on-cpu
> /pid == $1/
> {
>     on[tid] = vtimestamp/1000;
> }
>
> sched:::off-cpu
> /pid == $1 && on[tid]/
> {
>     @time[on[tid], vtimestamp/1000, on[tid] - lasttime[tid], tid, cpu] =
count();
You do not really want to aggregate here since you are literally tracing.
>     lasttime[tid] = on[tid];
>     on[tid] = 0;
> }
> dtrace:::END
> {
>     printa("%16d %16d %16d %6d %4d\n", @time);
>     trunc(@time);
> }
Try this:

BEGIN
{ clk = timestamp; }

on-cpu
{ t[cpu] = timestamp;
  self->onv = vtimestamp;
}

off-cpu
/self->onv/
{ printf("%16d %16d %16d %6d %4d\n", (t[cpu]-clk)/1000, (timestamp -
clk)/1000, (vtimestamp - self->onv)/1000, tid, cpu);
}


-- 
Just me,
Wire ...
Blog: <prstat.blogspot.com>

On 5/18/07, Wee Yeh Tan <weeyeh at gmail.com>
wrote:
> Try this:
>
> BEGIN
> { clk = timestamp; }
>
> on-cpu
/pid == $1/
> { t[cpu] = timestamp;
>   self->onv = vtimestamp;
> }
>
> off-cpu
> /self->onv/
> { printf("%16d %16d %16d %6d %4d\n", (t[cpu]-clk)/1000,
(timestamp -
> clk)/1000, (vtimestamp - self->onv)/1000, tid, cpu);
self->onv = 0;
> }
Missed your predicate & forgot to clear self->onv.  Problem the
magnetic send button.

btw, time-on/time-off now should reflect the ms after the dtrace
script started that your thread goes on/off the CPU & delta measures
the vtimestamp difference.

-- 
Just me,
Wire ...
Blog: <prstat.blogspot.com>

Jim,
    just a tangental note from the underground...


    self->XYZ
and
    XYZ[tid]

are effectively, for all practical purposes, the same.


except.....,  you can  @aggr[tid],  but you cannot  @aggr[self]


which means if, for whatever reason, you lean towards using "self"
you end up being forced to mix syntaxes in the end anyway :-(



-Pete.



in the example below

	self->st[tid]

causes an array st[] to be created for each kernel thread, and
in each thread only one element is defined, but it is a different
element for each thread

	st[tid]

causes one global array st[] to be created, and each thread accesses
it, but (again) it is a different element for each thread.

finally

	self->st

causes a scalar st to be created, one for each kernel thread.






 Mauro wrote On 05/17/07 06:44 PM,:
>>I read about the use of self-> and attempted to use that in my script
but
>>I still got strange results that suggested overlap.  I think I may have
>>that fixed but there is something I don''t understand.  If tid
is thread
>>ID, then isn''t it enough to have st[tid] without needing
self->?  If I
>>am wrong, can you explain why?
> 
> Good question, and I really should defer to someone that understands the
> variable scope in DTrace better than me (but that won''t stop me
from
> putting my foot in my mouth ... :^).
> 
> The use of "self->st[tid]" versus "st[tid]" alters
the scope of the
> variable.
> "self->" creates a thread-local variable, versus
"st[tid]", which defines
> a global variable. Variable scope is actually covered very well in the
> Solaris Dynamic Tracing Guide, and you can reference this:
> 
> http://www.opensolaris.org/jive/thread.jspa?messageID=67338&#67338
> 
> for more on global variables.
> 
> In the case of my test script, I''m using a predicate ( / pid ==
$target / )
> and running DTrace on a target process. So the probes firing from other
> threads going on and off cpu will not alter my data, since the action will
> not be taken as a result of the predicate evaluating false. It is for this
> reason I believe the use of a global or thread local variable yields the 
> same
> result.
> 
> HTH,
> /jim
> 
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org

On Fri, May 18, 2007 at 04:08:17PM -0700, Peter Lawrence
wrote:
>     just a tangental note from the underground...
> 
>     self->XYZ
> and
>     XYZ[tid]
> 
> are effectively, for all practical purposes, the same.
While the two could be used in the same context, the former should be used
since it is optimized to take advantage of the fact that thread-local
variables are necessarily contention free.

Adam

-- 
Adam Leventhal, Solaris Kernel Development       http://blogs.sun.com/ahl

On 5/19/07, Adam Leventhal <ahl at eng.sun.com>
wrote:
> On Fri, May 18, 2007 at 04:08:17PM -0700, Peter Lawrence wrote:
> >     just a tangental note from the underground...
> >
> >     self->XYZ
> > and
> >     XYZ[tid]
> >
> > are effectively, for all practical purposes, the same.
>
> While the two could be used in the same context, the former should be used
> since it is optimized to take advantage of the fact that thread-local
> variables are necessarily contention free.
Only if we are talking about the same pid of course.


-- 
Just me,
Wire ...
Blog: <prstat.blogspot.com>

Wee Yeh Tan wrote On 05/18/07 08:29 PM,:
> On 5/19/07, Adam Leventhal <ahl at eng.sun.com> wrote:
> 
>>On Fri, May 18, 2007 at 04:08:17PM -0700, Peter Lawrence wrote:
>>
>>>    just a tangental note from the underground...
>>>
>>>    self->XYZ
>>>and
>>>    XYZ[tid]
>>>
>>>are effectively, for all practical purposes, the same.
>>
>>While the two could be used in the same context, the former should be
used
>>since it is optimized to take advantage of the fact that thread-local
>>variables are necessarily contention free.
> 
> 
> Only if we are talking about the same pid of course.
> 
> 

Ooops, my big mistake, I was thinking of `did'' when I typed
`tid''


-Pete.

I''ld like my dtrace program to optionally take a command line
arg that is number-of-seconds to run, but have run out of creative
ideas trying.....

-Pete.

all of the following seem to fail one way or another when invoked
without a $1 command-line arg...


----------------------------------------------------------------
#!/usr/sbin/dtrace -s

profile-1
/ $1 && i++ == $1 /
{
        exit (0);
}

dtrace:::END
{
        printf ("goodbye!\n");
}


----------------------------------------------------------------
#!/usr/sbin/dtrace -s

int Expire;

dtrace:::BEGIN
{
        Expire = $1;
}

profile-1
/ Expire && i++ == Expire /
{
        exit (0);
}

dtrace:::END
{
        printf ("goodbye!\n");
}


----------------------------------------------------------------
#!/usr/sbin/dtrace -s -C

int Expire;

dtrace:::BEGIN
{
#if defined($1)
        Expire = $1;
#else
	Expire = 0;
#endif
}

profile-1
/ Expire && i++ == Expire /
{
        exit (0);
}

dtrace:::END
{
        printf ("goodbye!\n");
}

On Fri, May 18, 2007 at 09:13:03PM -0700, Peter Lawrence
wrote:
> 
> I''ld like my dtrace program to optionally take a command line
> arg that is number-of-seconds to run, but have run out of creative
> ideas trying.....
Did you try reading the DTrace Guide? There are also examples of doing
this in the DTraceToolkit. You need,

	#pragma D option defaultargs

Brendan

> -Pete.
> 
> all of the following seem to fail one way or another when invoked
> without a $1 command-line arg...
> 
> 
> ----------------------------------------------------------------
> #!/usr/sbin/dtrace -s
> 
> profile-1
> / $1 && i++ == $1 /
> {
>         exit (0);
> }
> 
> dtrace:::END
> {
>         printf ("goodbye!\n");
> }
> 
> 
> ----------------------------------------------------------------
> #!/usr/sbin/dtrace -s
> 
> int Expire;
> 
> dtrace:::BEGIN
> {
>         Expire = $1;
> }
> 
> profile-1
> / Expire && i++ == Expire /
> {
>         exit (0);
> }
> 
> dtrace:::END
> {
>         printf ("goodbye!\n");
> }
> 
> 
> ----------------------------------------------------------------
> #!/usr/sbin/dtrace -s -C
> 
> int Expire;
> 
> dtrace:::BEGIN
> {
> #if defined($1)
>         Expire = $1;
> #else
> 	Expire = 0;
> #endif
> }
> 
> profile-1
> / Expire && i++ == Expire /
> {
>         exit (0);
> }
> 
> dtrace:::END
> {
>         printf ("goodbye!\n");
> }
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org
-- 
Brendan
[CA, USA]

> The easiest way to track this is with prstat:
> 
> #prstat -Lp
--
This message posted from opensolaris.org