Dave Mitchell wrote:
thinking further, your best strategy is probably to include the dtrace
code in the PUSHSUB and POPSUB macros.
Would that catch everything, or would I still have to instrument (for
example) pp_entersub?
As a taster, here's a trace of the following perl script:
----------
#!/bin/perl
sub a { sleep(1); b(); }
sub b { sleep(1); c(); }
sub c { sleep(1); d(); }
sub d { sleep(1); }
while (1) { a(); }
----------
which I instrumented with the following primitive D script:
----------
#pragma D option quiet
perl_dtrace_execute$target:::function-entry
{
printf("PERL: %s %s:%d\n", copyinstr(arg0), copyinstr(arg1),
arg2);
}
pid$target:libc.so.1::entry
{
printf(" LIBC: %s\n", probefunc);
}
fbt:genunix::entry
/pid == $target/
{
printf(" KERNEL: %s\n", probefunc);
}
----------
It isn't pretty-indented as I've only implemented the entry point
tracing, but you get the idea - you can follow the process down from
perl, into libc, across the syscall barrier, into the kernel and back
out again. Not only could you use dtrace to profile your perl script,
you could use it to profile the OS at the same time. And if you want to
know what the kernel code is doing, go to http://opensolaris.org where
the source is available, e.g.
http://cvs.opensolaris.org/source/xref/usr/src/uts/common/os/callout.c#106
# LD_LIBRARY_PATH=$PWD PERL5LIB=$PWD/lib ./perl upanddown &
[1] 16508
# dtrace -s ./bryan.d -p 16508 | less
:
:
PERL: b upanddown:3
LIBC: time
LIBC: __time
KERNEL: syscall_mstate
KERNEL: gethrtime_unscaled
KERNEL: syscall_entry
KERNEL: pre_syscall
KERNEL: gtime
KERNEL: gethrestime
KERNEL: gethrtime
KERNEL: syscall_mstate
KERNEL: gethrtime_unscaled
KERNEL: syscall_mstate
KERNEL: gethrtime_unscaled
KERNEL: syscall_exit
KERNEL: post_syscall
KERNEL: thread_lock
KERNEL: disp_lock_exit
KERNEL: syscall_mstate
KERNEL: gethrtime_unscaled
LIBC: sleep
LIBC: ___nanosleep
KERNEL: syscall_mstate
KERNEL: gethrtime_unscaled
KERNEL: syscall_entry
KERNEL: pre_syscall
KERNEL: copyin_args32
KERNEL: copyin_nowatch
KERNEL: watch_disable_addr
KERNEL: nanosleep
KERNEL: gethrestime
KERNEL: gethrtime
KERNEL: timespecadd
KERNEL: cv_waituntil_sig
KERNEL: gethrestime
KERNEL: gethrtime
KERNEL: timespectohz_adj
KERNEL: timespecsub
KERNEL: timespecadd
KERNEL: cv_timedwait_sig
KERNEL: realtime_timeout
KERNEL: timeout_common
KERNEL: thread_lock
KERNEL: cv_block
KERNEL: new_mstate
KERNEL: gethrtime_unscaled
KERNEL: cpu_update_pct
KERNEL: scalehrtime
KERNEL: cpu_grow
KERNEL: cpu_decay
KERNEL: disp_lock_enter_high
KERNEL: disp_lock_exit_high
KERNEL: disp_lock_exit_nopreempt
KERNEL: disp_lock_enter
KERNEL: disp_lock_exit
KERNEL: restore_mstate
KERNEL: savectx
KERNEL: restorectx
KERNEL: untimeout
KERNEL: gethrestime
KERNEL: gethrtime
KERNEL: cv_waituntil_sig
KERNEL: gethrestime
KERNEL: gethrtime
KERNEL: timespectohz_adj
KERNEL: timespecsub
KERNEL: timespecadd
KERNEL: cv_timedwait_sig
KERNEL: realtime_timeout
KERNEL: timeout_common
KERNEL: thread_lock
KERNEL: cv_block
KERNEL: new_mstate
KERNEL: gethrtime_unscaled
KERNEL: cpu_update_pct
KERNEL: scalehrtime
KERNEL: cpu_grow
KERNEL: cpu_decay
KERNEL: disp_lock_enter_high
KERNEL: disp_lock_exit_high
KERNEL: disp_lock_exit_nopreempt
KERNEL: disp_lock_enter
KERNEL: disp_lock_exit
KERNEL: restore_mstate
KERNEL: savectx
KERNEL: restorectx
KERNEL: untimeout
KERNEL: gethrestime
KERNEL: gethrtime
KERNEL: syscall_mstate
KERNEL: gethrtime_unscaled
KERNEL: syscall_mstate
KERNEL: gethrtime_unscaled
KERNEL: syscall_exit
KERNEL: post_syscall
KERNEL: thread_lock
KERNEL: disp_lock_exit
KERNEL: syscall_mstate
KERNEL: gethrtime_unscaled
LIBC: time
LIBC: __time
KERNEL: syscall_mstate
KERNEL: gethrtime_unscaled
KERNEL: syscall_entry
KERNEL: pre_syscall
KERNEL: gtime
KERNEL: gethrestime
KERNEL: gethrtime
KERNEL: syscall_mstate
KERNEL: gethrtime_unscaled
KERNEL: syscall_mstate
KERNEL: gethrtime_unscaled
KERNEL: syscall_exit
KERNEL: post_syscall
KERNEL: thread_lock
KERNEL: disp_lock_exit
KERNEL: syscall_mstate
KERNEL: gethrtime_unscaled
LIBC: memcpy
PERL: c upanddown:4
LIBC: time
LIBC: __time
:
:
--
Alan Burlison
--
