On Thu, Jul 16, 2009 at 9:07 AM, Andrea
Cucciarre''<Andrea.Cucciarre at sun.com>
wrote:> Hi all,
>
> I''m trying to make a dscript that during the execution of a cp
(copy)
> command it prints the stat systemcalls that take more then 10000nanosec to
> complete and for each of that systemcalls it should also print the time
> spent in each functions of the ufs and pxfs kernel modules. Hereafter the
> script:
The first problem I see is that you keep resetting self->ts. The time
you''re going to report for your stat64 system call is actually going
to be the time between the last fbt::*fs:entry and
syscall::stat*:return. You probably want to use two separate
variables for that, e.g., self->syscallts and self->fbtts.
The second problem I see is that you keep resetting self->ts. The
time you report in fbt::fs*:return is not necessarily the time spent
in that function but rather the time since the last fbt::fs*:entry.
For example, if you have this function flow:
->a
->b
->c
<-c
<-b
<-a
the time you report spending in b is actually (b:return - c:entry).
Similarly for a, it''s (a:return - c:entry).
You probably want to do something like use a thread-local array and
manually keep track of your stack depth.
Chad
>
> inline int maxscall = 10000;
> #pragma D option flowindent=1
> #pragma D option nspec=100
>
> syscall::stat*:entry
> / execname == "cp" /
> {
> ??????? self->spec = speculation();
> ??????? self->ts = timestamp;
> }
>
> fbt:*fs::entry
> / self->spec /
> {
> ??????? self->ts = timestamp;
> }
>
> fbt:*fs::return
> / self->spec /
> {
> ??????? speculate(self->spec);
> ??????? printf("%d\n", timestamp - self->ts);
> }
>
> syscall::stat*:return
> / self->spec && timestamp - self->ts > maxscall /
> {
> ??????? speculate(self->spec);
> ??????? printf("SYSCALL %d\n\n", timestamp - self->ts);
> ??????? commit(self->spec);
> }
>
> syscall::stat*:return
> / self->spec /
> {
> ??????? discard(self->spec);
> ??????? self->spec = 0;
> }
>
> However I got an output like the following
>
> ? 1? <- __1cFpxdirJlc_lookup6MpcppnFvnode_rI_b_ 10115
> ? 1? <- __1cJpx_access6FpnFvnode_iipnEcred__i_ 5719
> ? 1? <- __1cMaccess_cacheGlookup6FipnEcred_pnKpxfobjplus__i_ 12089
> ? 1? <- __1cKpxfobjplusGaccess6MiipnEcred__i_ 18100
> ? 1? <- __1cFpxdirGlookup6MpcppnFvnode_pnIpathname_i3pnEcred__i_ 24240
> ? 1? <- __1cJpx_lookup6FpnFvnode_pcp1pnIpathname_i1pnEcred__i_ 29693
> ? 1? <- __1cKpx_getattr6FpnFvnode_pnFvattr_ipnEcred__i_ 5769
> ? 1? <- __1cFpxregJis_cached6M_b_???????????? 5489
> ? 1? <- __1cKpxfobjplusTget_attr_read_token6MpnEcred__i_ 5275
> ? 1? <- __1cLfobjplus_iiPget_attr_rights6MI_nHpxfs_v1Lattr_rights__ 5529
> ? 1? <-
> __1cLfobjplus_iiZdowngrade_attr_all_common6MnHpxfs_v1Lattr_rights_bIb_i_
> 7306
> ? 1? <-
__1cLfobjplus_iiWset_attr_rights_locked6MInHxfs_v1Lattr_rights__v_
> 6222
> ? 1? <- ufs_imark???????????????????????????? 8237
> ? 1? <- ufs_itimes_nolock???????????????????? 13435
> ? 1? <- ufs_getattr?????????????????????????? 20119
> ? 1? <-
>
__1cLfobjplus_iiPget_attr_common6MpnEcred_nHpxfs_v1Lattr_rights_rnDsolHvattr_t_rLbrnFCORBALEnvironment__v_
> 26212
> ? 1? <-
>
__1cLfobjplus_iiScache_get_all_attr6MpnGsolobjEcred_nHpxfs_v1Lattr_rights_rnDsolHvattr_t_rLrIrnFCORBALEnvironment__v_
> 32012
> ? 1? <-
>
__1cOfile_norm_implScache_get_all_attr6MpnGsolobjEcred_nHpxfs_v1Lattr_rights_rnDsolHvattr_t_rLrIrnFCORBALEnvironment__v_
> 37812
> ? 1? <- __1cHpxfslibHget_err6FkirnFCORBALEnvironment__i_ 4893
> ? 1? <- __1cKpxfobjplusMobtain_token6MnHpxfs_v1Lattr_rights_pnEcred__i_
> 13964
> ? 1? <- __1cFpxregJis_cached6M_b_???????????? 4889
> ? 1? <- __1cKpxfobjplusHgetattr6MpnFvattr_ipnEcred__i_ 10685
> ? 1? <= stat64??????????????????????????????? SYSCALL 22526
>
> As you can see in this stat64 we spent 22526 nanosec and in one of the pxfs
> function we spent 37812 nanosec.
> If the script would work as I expect the time spent during a pxfs/ufs
> function should always be less then the time spent for the stat systemcall.
> Moreover the flowindent doesn''t seem to work.
> Any advice?
>
>
> --
>
> /\ Andrea Cucciarre''
> \\ \ Systems Engineer
> \ \\ /
> / \/ / / Sun Microsystems Italia SpA
> / / \//\ Viale Fulvio Testi, 327
> \//\ / / 20162 Milano
> / / /\ /
> / \\ \ phone: 800 605228
> \ \\ e-mail: andrea.cucciarre at Sun.COM
> \/
>
>
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org
>