dtrace discuss - Oct 2009 - plockstat mutex hold output question

Hi,
I am having a bit of a problem understanding the following output from 
plockstat:

# plockstat -H -p `pgrep mcon`
 
Mutex hold

Count     nsec Lock                         Caller
-------------------------------------------------------------------------------
 
1955045     2195 libc.so.1`libc_malloc_lock   mcon`addwork+0x92
1949696     2196 libc.so.1`libc_malloc_lock   mcon`dowork+0x18b


 From taking a quick look at plockstat.c, the nsec column is a sum
of the number of nanoseconds that a mutex is held.  Count is a count
of the number of times the mutex is acquired. 
According to this output, a malloc lock is aquired and released
approximately 4 million times, but the total time spent holding the lock
is approximately 4000 nsecs.  So, on average, the lock is held for 
4000nsec/4000000
or .001 nsecs!!!  I did not think my machine was so fast!  If I use the 
plockstat
provider directly with dtrace, I get reasonable results.

So, is my arithmetic wrong, or is there another explanation?

thanks,
max

Hi Max,
>  From taking a quick look at plockstat.c, the nsec column is a sum
> of the number of nanoseconds that a mutex is held.  Count is a count
> of the number of times the mutex is acquired. According to this output, 
> a malloc lock is aquired and released
> approximately 4 million times, but the total time spent holding the lock
> is approximately 4000 nsecs.  So, on average, the lock is held for 
> 4000nsec/4000000
> or .001 nsecs!!!  I did not think my machine was so fast!  If I use the 
> plockstat
> provider directly with dtrace, I get reasonable results.
> 
> So, is my arithmetic wrong, or is there another explanation?
I think you''re just misreading the source. The ''nsec''
column is
the average duration of the event in nanoseconds. The plockstat(1M)
man page could probably do with a "display formats" section similar
to what lockstat(1M) has. I''ll file a doc bug.

Jon.

Hi Jon,

Jon Haslam wrote:
> Hi Max,
>
>>  From taking a quick look at plockstat.c, the nsec column is a sum
>> of the number of nanoseconds that a mutex is held.  Count is a count
>> of the number of times the mutex is acquired. According to this 
>> output, a malloc lock is aquired and released
>> approximately 4 million times, but the total time spent holding the
lock
>> is approximately 4000 nsecs.  So, on average, the lock is held for 
>> 4000nsec/4000000
>> or .001 nsecs!!!  I did not think my machine was so fast!  If I use 
>> the plockstat
>> provider directly with dtrace, I get reasonable results.
>>
>> So, is my arithmetic wrong, or is there another explanation?
>
> I think you''re just misreading the source. The
''nsec'' column is
> the average duration of the event in nanoseconds. The plockstat(1M)
> man page could probably do with a "display formats" section
similar
> to what lockstat(1M) has. I''ll file a doc bug.
Thanks.  You are right.  I saw the sum() aggregating function and assumed
that is what was displayed.  When the do the display, the divide the sum 
value
by the count value to get the average.

max
>
> Jon.
>