Is this behavior to be expected?
Not exactly. There will be a *some* delay as we've added a lot of new
functionality, but 800 ms total delay is excessive. I'll see if we can find the
culprit.
Could you please also try an "strace -r" to make sure I'm
not the only one seeing this?
Here's one of the relevant parts of my strace -r (FC4, 1GHZ athalon).
What stands out to me is that is that the sendto() and recvfrom() operations
aren't taking very long at all (remember, the relative time stamps are
*between* system calls, not *elapsed* during system calls). And since
recvfrom() is called with MSG_DONTWAIT, it's not going to block waiting for
data. Instead, there's a 100ms sleep before each recvfrom() that really racks
up the wait time. In total, I counted 9 places where su sleeps for 100ms
before a recvfrom() -- so that's almost 1 sec killed just sleeping.
I haven't dug through the code yet (which package is it in, anyway?), but I
can only imagine that the motivation for programming the thing like this (with
nanosleep + recvfrom w/ MSG_DONTWAIT) is to limit the amount of time spent
waiting for a reply. Obviously the reply takes *some* time to arrive, and
calling recvfrom() without MSG_DONTWAIT wouldn't be a viable option--you might
block forever. Hence, sleep long enough to give up a timeslice and hopefully
let the reply be generated, then check to see if its there.
A more reasonable solution (assuming it's possible with NETLINK sockets--I
don't know much about them) would be a select() with a maximum timeout of
100ms. That gives you worst-case performance equal to what we see now, with
the potential of much better.
Am I way off-base here, or does that sound like a good idea?
--------------
0.000100 bind(3, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 0
0.000543 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
0.000289 readlink("/proc/self/exe", "/bin/su", 4095) = 7
0.000495 sendto(3, "\20\0\0\0\350\3\5\0\5\0\0\0\0\0\0\0", 16, 0,
{sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 16
0.000371 nanosleep({0, 100000000}, NULL) = 0
0.101499 recvfrom(3,
"0\0\0\0\350\3\0\0\5\0\0\0Ey\0\0\0\0\0\0\1\0\0\0\1\0\0\0"..., 1216,
MSG_PEEK|MSG_DONTWAIT, {sa_family=AF_NETLINK, pid=0, groups=00000000}, [12]) = 48
0.000428 nanosleep({0, 100000000}, NULL) = 0
0.101554 recvfrom(3,
"0\0\0\0\350\3\0\0\5\0\0\0Ey\0\0\0\0\0\0\1\0\0\0\1\0\0\0"..., 1216,
MSG_DONTWAIT, {sa_family=AF_NETLINK, pid=0, groups=00000000}, [12]) = 48
0.000438 sendto(3, "l\0\0\0\355\3\5\0\6\0\0\0\0\0\0\0PAM session
open"..., 108, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 108
0.000600 nanosleep({0, 100000000}, NULL) = 0
0.101949 recvfrom(3,
"$\0\0\0\2\0\0\0\5\0\0\0Ey\0\0\0\0\0\0\20\0\0\0\350\3\5"..., 1216,
MSG_PEEK|MSG_DONTWAIT, {sa_family=AF_NETLINK, pid=0, groups=00000000}, [12]) = 36
0.000444 recvfrom(3,
"$\0\0\0\2\0\0\0\5\0\0\0Ey\0\0\0\0\0\0\20\0\0\0\350\3\5"..., 1216,
MSG_DONTWAIT, {sa_family=AF_NETLINK, pid=0, groups=00000000}, [12]) = 36
0.000442 close(3) = 0
--
fedora-devel-list mailing list
fedora-devel-list@xxxxxxxxxx
http://www.redhat.com/mailman/listinfo/fedora-devel-list
