[dtrace-discuss] Multiple returns from a syscall

[Adam Leventhal]

Hi Jesus,

Note that DTrace output is presented one CPU at a time rather than sorted
chronologically. Without seeing the full output from DTrace, one wouldn't
be able to draw any conclusions about a 'missing' entry. I suggest you
trace the timestamp in addition and then sort based on that column or
pbind the process to a specific CPU when doing this sort of analysis.

Adam

On Tue, Jun 05, 2007 at 08:58:46PM +0200, Jesus Cea wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
> 
> Trying to debug a very ugly issue (multisecond disk delays), found the
> following "impossible" info:
> 
> """
> ...
>   0  40286                   pwrite64:entry
>   0  40287                  pwrite64:return 36436
>   0  39998                     fdsync:entry 5379
>   1  39999                    fdsync:return 37918785 4
>   1  40286                   pwrite64:entry
>   1  40287                  pwrite64:return 69130
>   1  39998                     fdsync:entry 5394
>   0  39999                    fdsync:return 213396018 4
>   0  40286                   pwrite64:entry
>   0  40287                  pwrite64:return 22620
>   0  39998                     fdsync:entry 3993
>   0  40286                   pwrite64:entry
>   0  40287                  pwrite64:return 63125
>   0  39998                     fdsync:entry 5358
>   0  39999                    fdsync:return 35506247 4
>   1  39999                    fdsync:return 48140410 4
>   1  40286                   pwrite64:entry
>   1  40287                  pwrite64:return 52625
>   1  39998                     fdsync:entry 5068
>   1  39999                    fdsync:return 13777558 4
>   1  39999                    fdsync:return 7192502 4
> ...
> """
> 
> The "pwrite64:return" shows the time spend in the "pwrite64" syscall.
> The "fdsync:entry" number shows the delay between the "pwrite64"
> finishing and the "fdsync" syscall. The "fdsync:return" shows time spend
> in the fdsync. We can see this syscall is very slow (comparatively), as
> expected.
> 
> The issue is the last fragment: There is multiple "return" but only a
> single call. How can it be possible. What am I missing.
> 
> The dtrace code:
> 
> """
> [root at tesalia correo]# cat pwrite_y_fdsync.d
> self unsigned long long ts;
> 
> syscall::pwrite64:entry
> /pid==$1/
> {
>   printf(" ");
>   self->ts=timestamp;
> }
> 
> syscall::pwrite64:return
> /pid==$1 && self->ts/
> {
>   printf("%llu",timestamp-self->ts);
>   self->ts=timestamp;
> }
> 
> syscall::fdsync:entry
> /pid==$1/
> {
>   printf("%llu",timestamp-self->ts);
>   self->ts=timestamp;
> }
> 
> syscall::fdsync:return
> /pid==$1 && self->ts/
> {
>   printf("%llu %d",timestamp-self->ts,tid);
>   self->ts=0;
> }
> """
> 
> Solaris 10 Update 3 here.
> 
> Thanks in advance.
> 
> - --
> Jesus Cea Avion                         _/_/      _/_/_/        _/_/_/
> jcea at argo.es http://www.argo.es/~jcea/ _/_/    _/_/  _/_/    _/_/  _/_/
> jabber / xmpp:jcea at jabber.org         _/_/    _/_/          _/_/_/_/_/
>                                _/_/  _/_/    _/_/          _/_/  _/_/
> "Things are not so easy"      _/_/  _/_/    _/_/  _/_/    _/_/  _/_/
> "My name is Dump, Core Dump"   _/_/_/        _/_/_/      _/_/  _/_/
> "El amor es poner tu felicidad en la felicidad de otro" - Leibniz
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v1.4.6 (GNU/Linux)
> Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org
> 
> iQCVAwUBRmWyZplgi5GaxT1NAQLGPQP7BnOR7N4AspdM36R/wZBMX+S4Fhu7+JEI
> PA8VZaQninPCMZjHwlVoYDcf2BVbeY/9L9CKOlLLsuQaE18G5Zu66p3MXlbVHLhF
> VOJ64nHU2MFCyV1v863ypBimBFENxHE9X8gFCt4h/fKIAex6cSTdYzwM5irIRvsV
> iTPyE+GDWyo=
> =NL28
> -----END PGP SIGNATURE-----
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org

-- 
Adam Leventhal, Solaris Kernel Development       http://blogs.sun.com/ahl