dtrace discuss - Nov 2007 - Measure mutex contention with dtrace

Hi,

I''m looking for a way to measure mutex contention in a Java app running
on Solaris 10.  I started off by using the dvmti probes 
monitor-contended-enter and monitor-contended-entered, but I found that 
the act of observing these probes skewed my program performance to the 
point that the measurements weren''t useful.

I''m thinking of taking a lower-level approach to this.  Is it correct
to
assume that Java object monitors are going to map to a lwp_mutex at some 
point in the call stack?  I replaced my dvmti-based script with this:

syscall::lwp_mutex*:entry
{
   self->ts[probefunc] = timestamp;
}

syscall::lwp_mutex*:return
/self->ts[probefunc] != 0/
{
   duration = timestamp - self->ts[probefunc];
   @times[ tid ] = quantize( duration );
   self->ts[probefunc] = 0;
}

And the timings are pretty much what I''d expect, within an order of 
magnitude.  Can anybody suggest any improvements here, or am I totally 
off-base?

Thanks,

Russ

Russ,
I use some variation of the following attached script. It is derived from
plockstat sample code.
rick

On Thu, Nov 15, 2007 at 11:28:18AM -0800, Russ Weeks
wrote:
> 
> Hi,
> 
> I''m looking for a way to measure mutex contention in a Java app
running
> on Solaris 10.  I started off by using the dvmti probes 
> monitor-contended-enter and monitor-contended-entered, but I found that 
> the act of observing these probes skewed my program performance to the 
> point that the measurements weren''t useful.
> 
> I''m thinking of taking a lower-level approach to this.  Is it
correct to
> assume that Java object monitors are going to map to a lwp_mutex at some 
> point in the call stack?  I replaced my dvmti-based script with this:
> 
> syscall::lwp_mutex*:entry
> {
>    self->ts[probefunc] = timestamp;
> }
> 
> syscall::lwp_mutex*:return
> /self->ts[probefunc] != 0/
> {
>    duration = timestamp - self->ts[probefunc];
>    @times[ tid ] = quantize( duration );
>    self->ts[probefunc] = 0;
> }
> 
> And the timings are pretty much what I''d expect, within an order
of
> magnitude.  Can anybody suggest any improvements here, or am I totally 
> off-base?
> 
> Thanks,
> 
> Russ
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org
-- 

Rickey C. Weisner 
Software Development and Performance Specialist 
Sun Microsystems, INC
cell phone: 615-308-1147
email: rick.weisner at sun.com
-------------- next part --------------
#!/usr/sbin/dtrace -s

#pragma D option bufpolicy=ring
#pragma D option aggsize=256m
#pragma D option strsize=1024

plockstat$1:::rw-acquire
{
	self->rwhold[arg0] = timestamp;
}
plockstat$1:::mutex-acquire
/arg1 == 0 /
{
	mtxhold[arg0] = timestamp;
}
plockstat$1:::rw-release
/self->rwhold[arg0] && arg1 == 1/
{
	@rw_w_hold[arg0, jstack(5)] = avg(timestamp - self->rwhold[arg0]);
	self->rwhold[arg0] = 0;
}
plockstat$1:::rw-release
/self->rwhold[arg0]/
{
	@rw_r_hold[arg0, jstack(5)] = avg(timestamp - self->rwhold[arg0]);
	self->rwhold[arg0] = 0;
}
plockstat$1:::mutex-release
/mtxhold[arg0] && arg1 == 0/
{
	@mtx_hold[arg0, jstack(5)] = avg(timestamp - mtxhold[arg0]);
	mtxhold[arg0] = 0;
}
plockstat$1:::rw-block
{
	self->rwblock[arg0] = timestamp;
}
plockstat$1:::mutex-block
{
	self->mtxblock[arg0] = timestamp;
}
plockstat$1:::mutex-spin
{
	self->mtxspin[arg0] = timestamp;
}
plockstat$1:::rw-acquire
/self->rwblock[arg0] && arg1 == 1/
{
	@rw_w_block[arg0, jstack(5)] 	    avg(timestamp - self->rwblock[arg0]);
	self->rwblock[arg0] = 0;
}
plockstat$1:::rw-acquire
/self->rwblock[arg0]/
{
	@rw_r_block[arg0, jstack(5)] 	    avg(timestamp - self->rwblock[arg0]);
	self->rwblock[arg0] = 0;
}
plockstat$1:::mutex-block
/self->mtxspin[arg0]/
{
	@mtx_vain_spin[arg0, jstack(5)] 	    avg(timestamp - self->mtxspin[arg0]);
	self->mtxspin[arg0] = 0;
}
plockstat$1:::mutex-acquire
/self->mtxspin[arg0]/
{
	@mtx_spin[arg0, jstack(5)] 	    avg(timestamp - self->mtxspin[arg0]);
	self->mtxspin[arg0] = 0;
}
plockstat$1:::mutex-acquire
/self->mtxblock[arg0]/
{
	@mtx_block[arg0, jstack(5)] 	    avg(timestamp - self->mtxblock[arg0]);
	self->mtxblock[arg0] = 0;
}
plockstat$1:::mutex-error
/self->mtxblock[arg0]/
{
	self->mtxblock[arg0] = 0;
}
plockstat$1:::rw-error
/self->rwblock[arg0]/
{
	self->rwblock[arg0] = 0;
}
plockstat$1:::mutex-error
/self->mtxspin[arg0]/
{
	self->mtxspin[arg0] = 0;
}
tick-10sec
{
	trunc(@mtx_hold,10);
	trunc(@mtx_vain_spin,10);
	trunc(@mtx_spin,10);
	trunc(@mtx_block,10);
	printf(" mutex hold events =================================== \n");
	printa(@mtx_hold);
	printf(" mutex vain spin events ===================================
\n");
	printa(@mtx_vain_spin);
	printf(" mutex spin events =================================== \n");
	printa(@mtx_spin);
	printf(" mutex block events =================================== \n");
	printa(@mtx_block);
	clear(@mtx_hold);
	clear(@mtx_vain_spin);
	clear(@mtx_spin);
	clear(@mtx_block);
        exit(0);
}