Bug 167611 - socket delay on recv after send
socket delay on recv after send
Status: CLOSED NOTABUG
Product: Red Hat Enterprise Linux 4
Classification: Red Hat
Component: kernel (Show other bugs)
4.0
i386 Linux
medium Severity high
: ---
: ---
Assigned To: David Miller
Brian Brock
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2005-09-06 05:42 EDT by Richard Whitehurst
Modified: 2007-11-30 17:07 EST (History)
3 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2005-10-20 21:01:37 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Richard Whitehurst 2005-09-06 05:42:39 EDT
Description of problem:
Python CGI script delays by 5 seconds when reading from remote host via socket 
stream when tested on RHEL 4.  Previously worked with minimal delay on RHEL 3.

See strace (2.) below which illustrates a delay in select() of 4.580151 
seconds. In strace (1.) on RHEL 3 select() is not invoked by Python socket 
object and so no delay:

-------------------------------
1. RedHat Enterprise Linux 3 ES
# Repute
# Python 2.2.3 (#1, Aug  8 2003, 08:44:02)
# [GCC 3.2.3 20030502 (Red Hat Linux 3.2.3-13)] on linux2

[pid 20190] socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3 <0.000028>
[pid 20190] rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_IGN}, 8) = 0 <0.000016>
[pid 20190] connect(3, {sa_family=AF_INET, sin_port=htons(8895), 
sin_addr=inet_addr("xx.xx.xx.xx")}, 16) = 0 <0.020431>
[pid 20190] send(3, "<?xml version=\"1.0\"?>\r\n\t\t<Reques"..., 293, 0) = 293 
<0.000026>
[pid 20190] gettimeofday({1125948845, 81181}, NULL) = 0 <0.000015>
[pid 20190] recv(3, "<?xml version=\"1.0\" encoding=\"UT"..., 1024, 0) = 40 
<0.065814>
[pid 20190] gettimeofday({1125948845, 147165}, NULL) = 0 <0.000021>
[pid 20190] recv(3, "<!--\r\n  Generated by Easysoft XM"..., 1024, 0) = 378 
<0.019042>
[pid 20190] gettimeofday({1125948845, 166370}, NULL) = 0 <0.000019>
[pid 20190] close(3)                    = 0 <0.000036>


-------------------------------
2. RedHat Enterprise Linux 4 ES
# Byron
# Python 2.3.4 (#1, Feb  2 2005, 11:44:49)
# [GCC 3.4.3 20041212 (Red Hat 3.4.3-9.EL4)] on linux2

31616 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3 <0.000037>
31616 rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_IGN}, 8) = 0 <0.000012>
31616 connect(3, {sa_family=AF_INET, sin_port=htons(8895), sin_addr=inet_addr
("xx.xx.xx.x")}, 16)
 = 0 <0.016388>
31616 fcntl64(3, F_GETFL)               = 0x2 (flags O_RDWR) <0.000016>
31616 fcntl64(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000010>
31616 select(4, NULL, [3], NULL, {59, 0}) = 1 (out [3], left {59, 0}) <0.000018>
31616 send(3, "<?xml version=\"1.0\"?>\r\n\t\t<Reques"..., 293, 0) = 293 
<0.000038>
31616 gettimeofday({1125936280, 258608}, NULL) = 0 <0.000008>
31616 select(4, [3], NULL, NULL, {59, 0}) = 1 (in [3], left {54, 420000}) 
<4.580151>
31616 recv(3, "<?xml version=\"1.0\" encoding=\"UT"..., 1024, 0) = 40 <0.000018>
31616 gettimeofday({1125936284, 839183}, NULL) = 0 <0.000007>
31616 select(4, [3], NULL, NULL, {59, 0}) = 1 (in [3], left {58, 984000}) 
<0.016189>
31616 recv(3, "<!--\r\n  Generated by Easysoft XM"..., 1024, 0) = 378 <0.000012>
31616 gettimeofday({1125936284, 855667}, NULL) = 0 <0.000009>
31616 close(3)                          = 0 <0.000040>

------------------------------
3. Code used:

import socket

host = "xx.xx.xx.xx"
port = 8895
DSN  = "xxxxxxx_SQL;UID=sa;"
length = 1024

socket = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
socket.connect((host,port))

XML = ''
EOM = '</Result>'

bytecount = socket.send(Request)
while  XML[-10:-1] != EOM: 
	XML += socket.recv(length)

print XML

socket.close()


Version-Release number of selected component (if applicable):


How reproducible: every time


Steps to Reproduce:
1. run client script shown in description
2.
3.
  
Actual results:
Trivial CGI query takes > 4 seconds

Expected results:
Trivial CGI query takes < 1 second


Additional info:
Client script connects to XML-ODBC (EasySoft) service running on remote Windows 
server
Comment 1 Richard Whitehurst 2005-09-07 03:53:56 EDT
When same script run as non CGI script no select is generated and the same 
delay appears on the recv instead:

[pid  4932] connect(3, {sa_family=AF_INET, sin_port=htons(8895), 
sin_addr=inet_addr("80.168.60.156")}, 16) = 0 <0.016427>
[pid  4932] send(3, "<?xml version=\"1.0\"?>\r\n\t\t<Reques"..., 287, 0) = 287 
<0.000017>
[pid  4932] recv(3, "<?xml version=\"1.0\" encoding=\"UT"..., 1024, 0) = 40 
<4.556769>
[pid  4932] recv(3, "<!--\r\n  Generated by Easysoft XM"..., 1024, 0) = 378 
<0.017673>
[pid  4932] fstat64(1, {st_dev=makedev(0, 9), st_ino=3, st_mode=S_IFCHR|0620, 
st_nlink=1, st_uid=0, st_gid=5, st_blksize=1024, st_blocks=0, st_rdev=makedev
(136, 1), st_atime=2005/09/07-06:56:23, st_mtime=2005/09/07-06:56:23, 
st_ctime=2005/09/07-06:38:50}) = 0 <0.000056>
[pid  4932] mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -
1, 0) = 0xb7d70000 <0.000059>
[pid  4932] write(1, "<?xml version=\"1.0\" encoding=\"UT"..., 40) = 40 
<0.000124>
[pid  4932] write(1, "<!--\r\n", 6)     = 6 <0.000090>
[pid  4932] write(1, "  Generated by Easysoft XML-ODBC"..., 50) = 50 <0.000093>
Comment 2 Wade Mealing 2005-10-20 21:01:37 EDT
Looks as though the remote XML-ODBC was trying to reverse resolve the clients ip
address before doing a send(), possibly to log this information.

By turning this option off, the remote server responded instantly.

Note You need to log in before you can comment on or make changes to this bug.