David Jafferian - Sun Microsystems
2006-Jul-18 18:19 UTC
[dtrace-discuss] How to record waiters on mutex locks ?
Hi -
I wrote the following simple script :
---begin---
#!/usr/sbin/dtrace -s
BEGIN
{
lp = (int64_t)&`hat_statlock;
}
fbt::mutex_vector_enter:entry
/arg0 == lp/
{
waiters++;
}
lockstat:::adaptive-block
/arg0 == lp/
{
waiters--;
}
lockstat:::adaptive-spin
/arg0 == lp/
{
waiters--;
}
tick-10sec
{
trace(waiters);
}
---end---
Then I tested it on a two CPU sun4u machine as follows :
# cat /proc/self/pagedata >/dev/null &
885
# cat /proc/self/pagedata >/dev/null &
886
# ./test.d
dtrace: script ''./test.d'' matched 5 probes
CPU ID FUNCTION:NAME
1 37151 :tick-10sec 406
1 37151 :tick-10sec 815
1 37151 :tick-10sec 1230
1 37151 :tick-10sec 1536
1 37151 :tick-10sec 1913
1 37151 :tick-10sec 2296
1 37151 :tick-10sec 2700
1 37151 :tick-10sec 3078
...
I don''t see why "waiters" should increase over time.
--
David N. Jafferian
Solaris Kernel and Drivers
Product Technical Support
Sun Microsystems, Inc.
Jonathan Adams
2006-Jul-19 05:19 UTC
[dtrace-discuss] How to record waiters on mutex locks ?
On 7/18/06, David Jafferian - Sun Microsystems <david.jafferian at east.sun.com> wrote:> > > Hi - > > I wrote the following simple script : > > ---begin--- > #!/usr/sbin/dtrace -s > > BEGIN > { > lp = (int64_t)&`hat_statlock; > } > > fbt::mutex_vector_enter:entry > /arg0 == lp/ > { > waiters++; > } > > lockstat:::adaptive-block > /arg0 == lp/ > { > waiters--; > } > > lockstat:::adaptive-spin > /arg0 == lp/ > { > waiters--; > } > > tick-10sec > { > trace(waiters); > } > ---end--- > > Then I tested it on a two CPU sun4u machine as follows :...> I don''t see why "waiters" should increase over time.Global variables are not guaranteed to be consistant if modified from multiple threads. Try using an aggregation: s/waiters++/@a = sum(1)/ s/waiters--/@a = sum(-1)/ s/trace(waiters)/printa(@a)/ Cheers, - jonathan -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20060718/a36cd50b/attachment.html>
Jonathan Adams
2006-Jul-19 05:22 UTC
[dtrace-discuss] How to record waiters on mutex locks ?
On 7/18/06, Jonathan Adams <jwadams at gmail.com> wrote:> > On 7/18/06, David Jafferian - Sun Microsystems < > david.jafferian at east.sun.com> wrote: > > > > > Hi - > > > > I wrote the following simple script : > > > > ---begin--- > > #!/usr/sbin/dtrace -s > > > > BEGIN > > { > > lp = (int64_t)&`hat_statlock; > > } > > > > fbt::mutex_vector_enter:entry > > /arg0 == lp/ > > { > > waiters++; > > } > > > > lockstat:::adaptive-block > > /arg0 == lp/ > > { > > waiters--; > > } > > > > lockstat:::adaptive-spin > > /arg0 == lp/ > > { > > waiters--; > > } > > > > tick-10sec > > { > > trace(waiters); > > } > > ---end--- > > > > Then I tested it on a two CPU sun4u machine as follows : > > ... > > > I don''t see why "waiters" should increase over time. > > > Global variables are not guaranteed to be consistant if modified from > multiple threads. Try using an aggregation: > > s/waiters++/@a = sum(1)/ > s/waiters--/@a = sum(-1)/ > s/trace(waiters)/printa(@a)/ >In addition, with the recent putback of 6301220 <http://bugs.opensolaris.org/bugdatabase/view_bug.do?bug_id=6301220>Fix stats reporting so we do not lie about spins. into Nevada, a single mutex_vector_enter() can trigger both a block and a spin, which will break your script. Cheers, - jonathan -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20060718/c5cbe835/attachment.html>
Leon Koll
2007-Mar-25 09:12 UTC
[dtrace-discuss] Re: How to record waiters on mutex locks ?
Hello,
I am going to ask newbie questions so please forgive my illiteracy...
I''ve found this (discussion) thread when was trying to understand
what''s going on with my badly behaving NFS server that shows the
following lockstat statistics:
# lockstat -i 997 -Ikw sleep 60
Profiling interrupt: 250472 events in 62.806 seconds (3988 events/sec)
Count indv cuml rcnt nsec CPU+PIL Hottest Caller
-------------------------------------------------------------------------------
61221 24% 24% 0.00 2661 cpu[1] mutex_vector_enter
61112 24% 49% 0.00 2542 cpu[2] mutex_vector_enter
58961 24% 72% 0.00 2465 cpu[0] mutex_vector_enter
57524 23% 95% 0.00 2369 cpu[3] mutex_vector_enter
3684 1% 97% 0.00 2566 cpu[3]+3 mutex_enter
1678 1% 97% 0.00 2706 cpu[0]+6 e1000g_receive
1438 1% 98% 0.00 2895 cpu[2]+11 mutex_vector_enter
1408 1% 99% 0.00 2635 cpu[3]+11 setbackdq
1397 1% 99% 0.00 3140 cpu[1]+11 mutex_vector_enter
1360 1% 100% 0.00 2756 cpu[0]+11 mutex_vector_enter
332 0% 100% 0.00 2738 cpu[0]+9 dispatch_softint
206 0% 100% 0.00 2070 cpu[0]+10 set_anoninfo
78 0% 100% 0.00 5042 cpu[0]+2 dtrace_dynvar_clean
67 0% 100% 0.00 3842 cpu[2]+2 dtrace_dynvar_clean
3 0% 100% 0.00 2721 cpu[0]+1 mutex_vector_enter
2 0% 100% 0.00 2349 cpu[3]+5 ddi_io_put8
1 0% 100% 0.00 2283 cpu[2]+3 ddi_mem_put16
-------------------------------------------------------------------------------
The server details:
# uname -a
SunOS nfsbox 5.11 snv_59 i86pc i386 i86pc
# psrinfo -v
Status of virtual processor 0 as of: 03/25/2007 12:11:43
on-line since 03/22/2007 16:27:07.
The i386 processor operates at 2800 MHz,
and has an i387 compatible floating point processor.
Status of virtual processor 1 as of: 03/25/2007 12:11:43
on-line since 03/22/2007 16:27:24.
The i386 processor operates at 2800 MHz,
and has an i387 compatible floating point processor.
Status of virtual processor 2 as of: 03/25/2007 12:11:43
on-line since 03/22/2007 16:27:24.
The i386 processor operates at 2800 MHz,
and has an i387 compatible floating point processor.
Status of virtual processor 3 as of: 03/25/2007 12:11:43
on-line since 03/22/2007 16:27:24.
The i386 processor operates at 2800 MHz,
and has an i387 compatible floating point processor.
I modified the David''s script script according to Jonathan''s
advice:
#!/usr/sbin/dtrace -s
BEGIN
{
lp = (int64_t)&`hat_statlock;
}
fbt::mutex_vector_enter:entry
/arg0 == lp/
{
@a = sum(1);
}
lockstat:::adaptive-block
/arg0 == lp/
{
@a = sum(-1);
}
lockstat:::adaptive-spin
/arg0 == lp/
{
@a = sum(-1);
}
tick-10sec
{
printa(@a);
}
When the script is running, I can see only the ":tick-10sec" entries:
# ./dj.d
dtrace: script ''./dj.d'' matched 5 probes
CPU ID FUNCTION:NAME
2 70650 :tick-10sec
2 70650 :tick-10sec
What did I do wrong? How can I see which threads are waiting for the locks?
TIA,
[i]-- leon
[/i]
This message posted from opensolaris.org