[dtrace-discuss] Multiple returns from a syscall

[Jesus Cea]

-----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-----