[dtrace-discuss] Some of my nanoseconds are missing...

[Bryan Cantrill]

On Tue, Aug 08, 2006 at 05:58:43PM +0100, Nik Clayton wrote:
> ... almost 3,000,000,000,000 of them.
> 
> I'm instrumenting Sendmail (as some of you are probably bored of hearing).
> 
> Right now, I'm looking at where Sendmail spends its time when it's 
> creating queue files.
> 
> I've discovered that a lot of time is being spent in calls to fdsync().
> The set of numbers I'm using shows 3,255,859,582,382 nanoseconds being 
> spent in fdsync() for a given workload.

Is that virtual time (vtimestamp) or wall time (timestamp)?  And could
you send the script that determines the delta?  (A common mistake is
to store the timestamp on an entry, but forget to predicate the return
on the timestamp being non-zero -- potentially leading to an enormous
outlier.)

> So I set about instrumenting fdsync(), and counting the time consumed by 
>  the kernel calls it makes under the same workload.
> 
> Those figures show 286,960,093,086 nanoseconds taken up by kernel calls.
> 
> So where did the other 3,000... go?  And can I get DTrace to 
> (automatically?) show me where the time is being spent?  I know I can 
> use the lockstat provider to see how long I'm spending waiting for 
> locks, but presumably, since those locks are being waited for by kernel 
> functions I've already accounted for that time.

It depends if you're on CPU (vtimestamp) or off (timestamp).  Because
fdsync() almost certainly blocks, you might want to use the sched:::off-cpu 
probe to figure out where you're being taken off CPU and for how long.

> PS:  Any chance D could grow a pragma to automatically insert commas in 
> large numbers?  It would make comparing results much easier.

It's actually there -- kind of.  Expect mail from Mike soon... ;)

	- Bryan

--------------------------------------------------------------------------
Bryan Cantrill, Solaris Kernel Development.       http://blogs.sun.com/bmc