dtrace discuss - Feb 2008 - Measuring time spent doing each function in kernel.

Hey all -

Trying to track down a problem, I found that I wanted to understand how 
long each kernel function call was taking once inside a systemcall.

so, for example, let''s say, I wanted to look at fdsync() activity for a
given process, it might do something like

fdsync() entry
    function a entry
       function b entry
         function c entry
         function c return
         function c entry
         function c return
       function b return
       function b entry
         function c entry
         function c return
    function a return
    <...>
fdsync() return

Now: I''m sure someone has already solved this, so before I go working
it
out myself, what I want is something that will tell me how long each 
function was actually running and/or how long it was on CPU. Having both 
would be of advantage, considering that there might well be some waiting 
for disks etc.

Of course, the tricky part here is that I want both the running time of 
that function, both with and without the running time of it''s
subsequent
function calls...

So, some output from this mythical script might look like:

FUNCTION                   Entered(ms)Returned  Individual  Aggregate
fdsync() entry             0000000
    function a entry        0000400
       function b entry     0000500
         function c entry   0000600
         function c return              0000800         200        200
         function c entry   0001000
         function c return              0001200         200        200
       function b return                0001300         400        800
       function b entry     0001400
         function c entry   0001500
         function c return              0001600         100        100
       function b return                0001700         200        300
    function a return                   0001900         300       1500
    <...>
fdsync() return

Of course, if someone has something already written that''s even close
to
this, it would be excellent... and being able to limit the depth or 
functions we track would also be cool... ;)

Thanks for any thoughts!

Nathan.

Hi

Give the attach script a try.

It takes as an argument the name of the function.  Couple pieces of 
information
1) It will gather 20 traces then exit.  You can change that by change 
the value 20 in the script
2) Some of the stack traces can get rather long, so record the output by 
some means.
3) I have seen it in certain scenarios have a significant impact on the 
performance of the system.

Hope this provides you with at least a base to start with, it has proven 
useful on this end on
tracking down performance issues.

Dave V

Nathan Kroenert wrote:
> Hey all -
>
> Trying to track down a problem, I found that I wanted to understand how 
> long each kernel function call was taking once inside a systemcall.
>
> so, for example, let''s say, I wanted to look at fdsync() activity
for a
> given process, it might do something like
>
> fdsync() entry
>     function a entry
>        function b entry
>          function c entry
>          function c return
>          function c entry
>          function c return
>        function b return
>        function b entry
>          function c entry
>          function c return
>     function a return
>     <...>
> fdsync() return
>
> Now: I''m sure someone has already solved this, so before I go
working it
> out myself, what I want is something that will tell me how long each 
> function was actually running and/or how long it was on CPU. Having both 
> would be of advantage, considering that there might well be some waiting 
> for disks etc.
>
> Of course, the tricky part here is that I want both the running time of 
> that function, both with and without the running time of it''s
subsequent
> function calls...
>
> So, some output from this mythical script might look like:
>
> FUNCTION                   Entered(ms)Returned  Individual  Aggregate
> fdsync() entry             0000000
>     function a entry        0000400
>        function b entry     0000500
>          function c entry   0000600
>          function c return              0000800         200        200
>          function c entry   0001000
>          function c return              0001200         200        200
>        function b return                0001300         400        800
>        function b entry     0001400
>          function c entry   0001500
>          function c return              0001600         100        100
>        function b return                0001700         200        300
>     function a return                   0001900         300       1500
>     <...>
> fdsync() return
>
> Of course, if someone has something already written that''s even
close to
> this, it would be excellent... and being able to limit the depth or 
> functions we track would also be cool... ;)
>
> Thanks for any thoughts!
>
> Nathan.
>
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org
>   
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: time_stamp
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20080221/e97043a1/attachment.ksh>

Brenden Gregg''s DTraceToolkit has some scripts that gather inclusive
and exclusive function times. I know there is one for the hotspot provider
(j_calltime.d), if there isn''t one for fbt it be easy to modify the
hotspot one.


--
This message posted from opensolaris.org