Rao Shoaib
2006-Sep-12 23:35 UTC
[dtrace-discuss] dtrace reports different counts depending on what is being traced
We are using following dtrace script to analyze an application. However
we see different number of lwp_yield and yield calls reported depending
on whether we trace mutex_lock or mutex_unlock or not. The number
reported when we are not tracing mutex_lock or mutex_unlock is higher.
What could be going on here and which one is the correct number. This is
on S10 U2.
Thanks,
Rao.
#!/usr/sbin/dtrace -qs
syscall::yield:entry
/execname=="rrcpd"/
{
@[probefunc]=count();
}
pid$1:libc:lwp_yield:entry
{
@[probefunc]=count();
}
pid$1:libc:mutex_lock:entry
{
@[probefunc]=count();
}
pid$1:libc:mutex_unlock:entry
{
@[probefunc]=count();
}
tick-10s { exit(0);}
2345 x4100-240-02 /export/home/dtrace/PIT > ./yield_lwp_count.d `pgrep
rrcpd`
lwp_yield 571
yield 572
mutex_lock 2394464
mutex_unlock 2394562
2358 x4100-240-02 /export/home/dtrace/PIT > ./yield_lwp_count.d `pgrep
rrcpd`
lwp_yield 4191
yield 4191
mutex_unlock 2401667
Chip Bennett
2006-Sep-13 12:30 UTC
[dtrace-discuss] dtrace reports different counts depending on what is being traced
Rao, Your explanation implies that you edited the D script between the two runs, and removed the probe clause for mutex_lock. I don''t want to assume without asking, so is this correct? Thanks, Chip Rao Shoaib wrote:> We are using following dtrace script to analyze an application. > However we see different number of lwp_yield and yield calls reported > depending on whether we trace mutex_lock or mutex_unlock or not. The > number reported when we are not tracing mutex_lock or mutex_unlock is > higher. What could be going on here and which one is the correct > number. This is on S10 U2. > > Thanks, > > Rao. > > > #!/usr/sbin/dtrace -qs > > syscall::yield:entry > /execname=="rrcpd"/ > { > @[probefunc]=count(); > } > > pid$1:libc:lwp_yield:entry > { > @[probefunc]=count(); > } > > pid$1:libc:mutex_lock:entry > { > @[probefunc]=count(); > } > > pid$1:libc:mutex_unlock:entry > { > @[probefunc]=count(); > } > tick-10s { exit(0);} > > 2345 x4100-240-02 /export/home/dtrace/PIT > ./yield_lwp_count.d `pgrep > rrcpd` > > lwp_yield 571 > yield 572 > mutex_lock 2394464 > mutex_unlock 2394562 > > > 2358 x4100-240-02 /export/home/dtrace/PIT > ./yield_lwp_count.d `pgrep > rrcpd` > > > lwp_yield 4191 > yield 4191 > mutex_unlock 2401667 > > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org
Roch - PAE
2006-Sep-13 12:36 UTC
[dtrace-discuss] dtrace reports different counts depending on what is being traced
Chip Bennett writes:
> Rao,
>
> Your explanation implies that you edited the D script between the two
> runs, and removed the probe clause for mutex_lock. I don''t want
to
> assume without asking, so is this correct?
>
> Thanks,
> Chip
>
> Rao Shoaib wrote:
> > We are using following dtrace script to analyze an application.
> > However we see different number of lwp_yield and yield calls reported
> > depending on whether we trace mutex_lock or mutex_unlock or not. The
> > number reported when we are not tracing mutex_lock or mutex_unlock is
> > higher. What could be going on here and which one is the correct
> > number. This is on S10 U2.
> >
> > Thanks,
> >
> > Rao.
> >
> >
> > #!/usr/sbin/dtrace -qs
> >
> > syscall::yield:entry
> > /execname=="rrcpd"/
> > {
> > @[probefunc]=count();
> > }
> >
> > pid$1:libc:lwp_yield:entry
> > {
> > @[probefunc]=count();
> > }
> >
> > pid$1:libc:mutex_lock:entry
> > {
> > @[probefunc]=count();
> > }
> >
> > pid$1:libc:mutex_unlock:entry
> > {
> > @[probefunc]=count();
> > }
> > tick-10s { exit(0);}
> >
> > 2345 x4100-240-02 /export/home/dtrace/PIT > ./yield_lwp_count.d
`pgrep
> > rrcpd`
> >
> > lwp_yield 571
> > yield 572
> > mutex_lock 2394464
> > mutex_unlock 2394562
> >
> >
> > 2358 x4100-240-02 /export/home/dtrace/PIT > ./yield_lwp_count.d
`pgrep
> > rrcpd`
> >
> >
> > lwp_yield 4191
> > yield 4191
> > mutex_unlock 2401667
> >
> > _______________________________________________
> > dtrace-discuss mailing list
> > dtrace-discuss at opensolaris.org
>
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org
Eisenberg potentially at work here.
Knowing something about the situation, the yield() are
called as the application is waiting for data from the
network.
By instrumenting, commonly used mutexes, we slow down the
application enough that when it looks at the network, data is
more commonly present and it needs not yield().
A hypothesis.
-r
Rao Shoaib
2006-Sep-13 16:19 UTC
[dtrace-discuss] dtrace reports different counts depending on what is being traced
Roch - PAE wrote:> Eisenberg potentially at work here. > > Knowing something about the situation, the yield() are > called as the application is waiting for data from the > network. > > By instrumenting, commonly used mutexes, we slow down the > application enough that when it looks at the network, data is > more commonly present and it needs not yield(). > > A hypothesis. > >Well the other interesting observation we have is that when we run the same binary on S10 U2 we see much more calls to yield compared to U1. Dtrace shows us that the application is calling mutex unlock which results in calling yield. However when we count the calls to mutex_unlock we see the same number of calls being made by the application in both U1 and U2. rao.