dtrace discuss - Feb 2008 - measuring sleep time in synchronization objects

Hi,

 

I am fairly new to DTrace, and wanted to ask something regarding
synchronization objects.

 

I have a multithreaded C++ program in which I use semaphores (POSIX version)
for synchronization. I was interested in using DTrace to figure out the
total time for which each thread in my application sleeps, blocked on a
semaphore, i.e., as a result of sem_wait() call. In order to measure this, I
wrote a script with sched:::sleep and sched:wakeup probes enabled, as shown
below:

 

sched:::sleep

/execname == "myexecname"/

{

    ustack();

    bedtime[curlwpsinfo->pr_addr,curlwpsinfo->pr_stype] = walltimestamp;

}

 

sched:::wakeup

/bedtime[args[0]->pr_addr,args[0]->pr_stype]/

{

 
@sleeptime[execname,args[0]->pr_lwpid,args[0]->pr_addr,args[0]->pr_stype]
sum(walltimestamp - bedtime[args[0]->pr_addr,args[0]->pr_stype]);

    bedtime[args[0]->pr_addr,args[0]->pr_stype] = 0;

}

 

On running my program along with this script, I could see (because of
ustack()) that the program is following the expected path to sem_wait() call
and then enters cv_block:sleep. The aggregation output showed that the
threads in my program are sleeping on pr_stype = 3 (translates to SOBJ_CV
according to the file sobject.h). However, I was expecting to see the
threads sleeping on pr_stype = 5 (SOBJ_USER) as a result of sem_wait()
calls, because the description of pr_stype field in struct lwpsinfo_t says
that (and I quote from chapter 25 of the DTrace guide):

 

The pr_stype field is set when the thread is sleeping on a synchronization
object.

The possible values for the pr_stype field are:

SOBJ_MUTEX

SOBJ_RWLOCK

...

SOBJ_USER : A user-level synchronization object. All blocking on user-level

synchronization objects is handled with SOBJ_USER synchronization

objects. User-level synchronization objects include those created with

mutex_init(3), sema_init(3C), rwlock_init(3C),

cond_init(3C) and their POSIX equivalents.

...

SOBJ_SHUTTLE

 

I was not surprised that the threads are sleeping on other synchronization
objects as well, but no account of SOBJ_USER was a little surprising.

Although I can see from ustack() that sem_wait() ultimately leads to
cv_block:sleep, was I wrong in expecting to see pr_stype = SOBJ_USER in the
output? Can someone please explain what is going on?

 

In case this is not the correct forum for such questions, please direct me
to a suitable forum. Thank you for your time.

 

Regards,

Priya

 

-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20080212/f08ae2e2/attachment.html>

Hi Priya,

Sorry for taking so long to get back to you. This appears to be a  
subtle difference
between the documented behavior and what''s actually implemented. In  
most cases, user-
land synchronization primitives will call lwp_block() which shows up  
as SOBJ_USER, but
some cases call lwp_park() which calls cv_waituntil_sig() so shows up  
as SOBJ_CV.

I''d argue that this is a bug, but libc guru Roger Faulkner may want to
weigh in.

Adam

On Feb 12, 2008, at 12:50 PM, Priya Natarajan wrote:
> Hi,
>
> I am fairly new to DTrace, and wanted to ask something regarding  
> synchronization objects.
>
> I have a multithreaded C++ program in which I use semaphores (POSIX  
> version) for synchronization. I was interested in using DTrace to  
> figure out the total time for which each thread in my application  
> sleeps, blocked on a semaphore, i.e., as a result of sem_wait()  
> call. In order to measure this, I wrote a script with sched:::sleep  
> and sched:wakeup probes enabled, as shown below:
>
> sched:::sleep
> /execname == ?myexecname?/
> {
>     ustack();
>     bedtime[curlwpsinfo->pr_addr,curlwpsinfo->pr_stype] =  
> walltimestamp;
> }
>
> sched:::wakeup
> /bedtime[args[0]->pr_addr,args[0]->pr_stype]/
> {
>     @sleeptime[execname,args[0]->pr_lwpid,args[0]->pr_addr,args[0]- 
> >pr_stype] = sum(walltimestamp - bedtime[args[0]->pr_addr,args[0]- 
> >pr_stype]);
>     bedtime[args[0]->pr_addr,args[0]->pr_stype] = 0;
> }
>
> On running my program along with this script, I could see (because  
> of ustack()) that the program is following the expected path to  
> sem_wait() call and then enters cv_block:sleep. The aggregation  
> output showed that the threads in my program are sleeping on  
> pr_stype = 3 (translates to SOBJ_CV according to the file  
> sobject.h). However, I was expecting to see the threads sleeping on  
> pr_stype = 5 (SOBJ_USER) as a result of sem_wait() calls, because  
> the description of pr_stype field in struct lwpsinfo_t says that  
> (and I quote from chapter 25 of the DTrace guide):
>
> The pr_stype field is set when the thread is sleeping on a  
> synchronization object.
> The possible values for the pr_stype field are:
> SOBJ_MUTEX
> SOBJ_RWLOCK
> ...
> SOBJ_USER : A user-level synchronization object. All blocking on  
> user-level
> synchronization objects is handled with SOBJ_USER synchronization
> objects. User-level synchronization objects include those created with
> mutex_init(3), sema_init(3C), rwlock_init(3C),
> cond_init(3C) and their POSIX equivalents.
> ...
> SOBJ_SHUTTLE
>
> I was not surprised that the threads are sleeping on other  
> synchronization objects as well, but no account of SOBJ_USER was a  
> little surprising.
> Although I can see from ustack() that sem_wait() ultimately leads to  
> cv_block:sleep, was I wrong in expecting to see pr_stype = SOBJ_USER  
> in the output? Can someone please explain what is going on?
>
> In case this is not the correct forum for such questions, please  
> direct me to a suitable forum. Thank you for your time.
>
> Regards,
> Priya
>
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org

--
Adam Leventhal, Fishworks                        http://blogs.sun.com/ahl