Why apache is recv()-ing something for 15 sec every time?

Question

I have ZendFramework based application that is using XMLRPC communication to other ZendFramework app. Both are on the same server (for development). That communication is very slow, and I am trying to find out why. After profiling, I got to the point where there is a slowdown within fgets() of ZF Lib XMLRPC reader.

While strace-ing ZendFramework based PHP Application, I get some patterns with recv() waiting for 15 seconds? Anyone have any idea why is this might be happening?

 0.000038 gettimeofday({1278333900, 86101}, NULL) = 0
 0.000037 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 32
 0.000035 fcntl64(32, F_GETFL)      = 0x2 (flags O_RDWR)
 0.000033 fcntl64(32, F_SETFL, O_RDWR|O_NONBLOCK) = 0
 0.000034 connect(32, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
 0.000076 poll([{fd=32, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 120000) = 1 ([{fd=32, revents=POLLOUT}])
 0.000045 getsockopt(32, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
 0.000036 fcntl64(32, F_SETFL, O_RDWR) = 0
 0.000113 send(32, "POST /r/?articleId=554&hpr=Pimpl"..., 1180, MSG_DONTWAIT) = 1180
 0.000148 poll([{fd=32, events=POLLIN|POLLERR|POLLHUP}], 1, 120000) = 1 ([{fd=32, revents=POLLIN}])
 0.028020 recv(32, "HTTP/1.1 200 OK\r\nDate: Mon, 05 J"..., 8192, MSG_DONTWAIT) = 543
 0.000105 poll([{fd=32, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 0 (Timeout)
 0.000050 poll([{fd=32, events=POLLIN|POLLERR|POLLHUP}], 1, 120000) = 1 ([{fd=32, revents=POLLIN}])
15.012976 recv(32, "", 8192, MSG_DONTWAIT) = 0
 0.000123 close(32)                 = 0

Answer 1

I know little about ZendFramework so take my comments with a grain of salt... but!

If I understand this correctly

0.000050 poll([{fd=32, events=POLLIN|POLLERR|POLLHUP}], 1, 120000) = 1 ([{fd=32, revents=POLLIN}])
15.012976 recv(32, "", 8192, MSG_DONTWAIT) = 0

It means that you are polling on the socket (32) you get a signal POLLIN (incoming data) you go to recv and wait for 15 seconds (timeout) getting 0 bytes back

This to me would indicate a bug. probably in the zendframework or perhaps how you are calling it. receiving 0 bytes after a recv indicates the socket was cleanly closed (as opposed to forced shut). Therefore when you come out of poll and go into recv the response should be immediate (its only reading 0 bytes after all)

The MSG_DONTWAIT flag I assume means to go into non blocking mode which means that irrespective of the data waiting it should return immediately, either with data or with a wouldblock error, to return into the polling loop.

It may possibly be that something else is freezing the thread causing this to lockup. try placing the apps on two different machines to see if you get the same error. it may be some weird interaction.

DC