Re: long poll() delay

[Stefan Urbanek]

Richard Frith-Macdonald wrote:
> 
> On Wednesday, May 29, 2002, at 02:39 PM, Stefan Urbanek wrote:
> 
> > Richard Frith-Macdonald wrote:
> >>
> >> I'd suggest running the app under strace to log system calls, and see
> >> what
> >> the poll is waiting for.
> >>
> >
> > Output from strace (with -rTv options) between the first two poll
> > NSLogs:
> >
> >      0.000920 write(2, "2002-05-29 15:32:17.547 Farmer[1"..., 49) = 49
> > <0.000278>
> >      0.000659 poll([{fd=4, events=POLLOUT}], 1, 18358) = 0 <18.368170>
> >     18.388649 getpid()                  = 18432 <0.000007>
> >      0.000112 gettimeofday({1022679155, 937848}, NULL) = 0 <0.000007>
> >      0.000426 write(2, "2002-05-29 15:32:35.937 Farmer[1"..., 47) = 47
> > <0.000265>
> >
> > What more information is necessary to trace where the problem is?
> 
> More context ... we know it's polling on fd 4, but we don't know what
> fd 4
> is and what has been done to it.  My guess is that it's a socket on which
> an async connect attempt has been initiated to talk to gdomap.
> 
Here it is:
...   
     0.006400 close(4)                  = 0 <0.000012>
     0.000056 munmap(0x404b2000, 4096)  = 0 <0.000021>
     0.000302 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 4 <0.000037>
     0.049664 fstat(4, {st_dev=makedev(0, 0), st_ino=500174,
st_mode=S_IFSOCK|0777, st_nlink=1, st_uid=101, st_gid=101,
st_blksize=4096, st_blocks=8, st_size=0, st_atime=2002/05/23-22:45:57,
st_mtime=2001/03/03-03:38:38, st_ctime=2002/05/23-22:30:35}) = 0
<0.000019>
     0.003529 fcntl(4, F_GETFL)         = 0x2 (flags O_RDWR) <0.000008>
     0.000150 fcntl(4, F_GETFL)         = 0x2 (flags O_RDWR) <0.000008>
     0.000060 fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000007>
     0.000128 connect(4, {sin_family=AF_INET, sin_port=htons(538),
sin_addr=inet_addr("147.175.99.31")}}, 16) = -1 EINPROGRESS (Operation
now in progress) <0.000126>
     0.000501 gettimeofday({1022679137, 546879}, NULL) = 0 <0.000009>
     0.000113 gettimeofday({1022679137, 546970}, NULL) = 0 <0.000007>
     0.000078 gettimeofday({1022679137, 547050}, NULL) = 0 <0.000007>
     0.000350 getpid()                  = 18432 <0.000009>
     0.000110 gettimeofday({1022679137, 547508}, NULL) = 0 <0.000007>
     0.000920 write(2, "2002-05-29 15:32:17.547 Farmer[1"..., 49) = 49
<0.000278>
     0.000659 poll([{fd=4, events=POLLOUT}], 1, 18358) = 0 <18.368170>
    18.388649 getpid()                  = 18432 <0.000007>
     0.000112 gettimeofday({1022679155, 937848}, NULL) = 0 <0.000007>
     0.000426 write(2, "2002-05-29 15:32:35.937 Farmer[1"..., 47) = 47
<0.000265>
...
> >> My guess is it's trying to contact gdomap on the remote host, and the
> >> connection attempt is taking a while to time out rather than failing
> >> instantly.
> >>
> >> Only after failing to find the required server on the remote host will
> >> it attempt to talk to an alternative on the local host.
> >>
> >
> > I do not understand, why it is trying to contact gdomap on the remote
> > host? Everything is being run on the same host, only the X serer
> > (display) is remote (in relation to the application).
> 
> Because it's displaying on a remote host ... so it knows it needs to talk
> to the distributed notification center and pasteboard server for that
> host.
> The default assumption is that they will be running on that host, so it
> needs to ask gdomap on that host for the IP port numbers on which they
> can be reached.
> Only if it can't find them there will it look for them elsewhere on the
> network.
> 

Thank you for the explanation.

> Perhaps it might be worth adding a default to reverse the order in which
> the system looks for these servers, or alternatively using a shorter
> timeout.

This is a good idea.