Dtrace : calculating time spent in functions

The other day (10th Feb 2005), I was giving a demo of Dtrace to BEA India folks in ITPL Bangalore and thought that having a Dtrace script which could demonstrate following things would be nice :-

(a) time spent in functions called
(b) shows both user and kernel level tracing capabilities in the same function call context.
(c) uses $target and -c to demonstrate tracing when a process is launched.

I hope people would find it interesting. Here is the output from script. Please note that the time spent is expressed in nanoseconds.

# which w
/usr/bin/w
# dtrace -c w -Fs ./userfunc.target.d main
[.]
 5  -> malloc                                        0
 5    -> assert_no_libc_locks_held                   0
 5    <- assert_no_libc_locks_held                        6880
 5    -> lmutex_lock                                 0
 5    <- lmutex_lock                                      7840
 5    -> _malloc_unlocked                            0
 5      -> cleanfree                                 0
 5      <- cleanfree                                      7600
 5      -> realfree                                  0
 5      <- realfree                                       8000
 5    <- _malloc_unlocked                                35360
 5    -> lmutex_unlock                               0
 5    <- lmutex_unlock                                    8240
 5  <- malloc                                            89200
 5  -> sysinfo                                       0              <-------- getting into kernel
 5    -> pre_syscall                                 0
 5      -> syscall_mstate                            0
 5      <- syscall_mstate                                 4560
 5    <- pre_syscall                                     13120
 5    -> systeminfo                                  0
 5    <- systeminfo                                       5760
 5    -> post_syscall                                0
 5      -> clear_stale_fd                            0
 5      <- clear_stale_fd                                 5200
 5      -> syscall_mstate                            0
 5      <- syscall_mstate                                 4000
 5    <- post_syscall                                    21680

 5  <- sysinfo                                           60720
[.]

# cat userfunc.target.d
/*
* This script calculates time spent in all the functions (userland & kernel)
* called once a particular function is traced.
*
* Please see /usr/demo/dtrace/userfunc.d also.
*
* Usage:
* # dtrace -c  -Fs ./userfunc.target.d 
*/

BEGIN
{
       self->depth = 0;
}

pid$target::$1:entry
{
       self->trace = 1;
       self->depth = 0;
       self->timestamp[self->depth++] = timestamp;
}

pid$target::$1:return
/self->trace/
{
       self->trace = 0;
       trace(timestamp - self->timestamp[0]);
}

fbt:::entry,
pid$target:::entry
/self->trace && self->timestamp[self->depth - 1]/
{
       self->timestamp[self->depth++] = timestamp;
       trace(0);
}

fbt:::return,
pid$target:::return
/self->trace && self->timestamp[self->depth - 1]/
{
       self->depth--;
       trace(timestamp - self->timestamp[self->depth]);
       self->timestamp[self->depth] = 0;
}