2007-07-26 20:18:04.375 [3317] GS: Got response from sendDataPending
2007-07-26 20:18:04.376 [3317] GS: Calling poll with timeout 60000
2007-07-26 20:18:04.376 [3317] GS: Checking poll results
2007-07-26 20:18:04.376 [3317] GS: calling SSL_write on buffer of
length 1281
2007-07-26 20:18:04.376 [3317] GS: done with SSL_write
2007-07-26 20:18:04.376 [3317] Called advanceSendBuffer:len
2007-07-26 20:18:04.377 [3317] GS: Calling poll with timeout 60000
2007-07-26 20:18:04.426 [3317] GS: Checking poll
results <------------- 50ms delay occurs here
2007-07-26 20:18:04.426 [3317] GS: calling SSL_read
2007-07-26 20:18:04.427 [3317] GS: done with SSL_read, len = 142,
text = GET
And if you run tcpdump on the TCP packets, does it also agree there
is a 50ms delay ? which end is causing the delay ?
I ran a session with tcpdump on the server, stepping the client in a
debugger, and I am having some trouble interpreting the results. The
tcpdump output for a session is as followed (I've filtered to show
only TCP transmissions in both directions with the client, and
replaced the host names with CLIENT and SERVER):
21:08:30.190534 CLIENT.39044 > SERVER.8443: P 844:1025(181) ack 4827
win 65535 <nop,nop,timestamp 173778704 299402767> (DF)
21:08:30.199567 SERVER.8443 > CLIENT.39044: P 4827:4917(90) ack 1025
win 8576 <nop,nop,timestamp 299406197 173778704> (DF)
21:08:30.202752 SERVER.8443 > CLIENT.39044: . 4917:6285(1368) ack
1025 win 8576 <nop,nop,timestamp 299406200 173778704> (DF)
21:08:30.290932 CLIENT.39044 > SERVER.8443: . ack 4917 win 65535
<nop,nop,timestamp 173778704 299406197> (DF)
21:08:30.290977 SERVER.8443 > CLIENT.39044: P 6285:6483(198) ack 1025
win 8576 <nop,nop,timestamp 299406288 173778704> (DF)
21:08:30.366362 CLIENT.39044 > SERVER.8443: . ack 6285 win 65535
<nop,nop,timestamp 173778704 299406200> (DF)
21:08:30.382245 CLIENT.39044 > SERVER.8443: . ack 6483 win 65466
<nop,nop,timestamp 173778704 299406288> (DF)
The server logs for this time period (on the same machine, so
timestamps should match) show this (I'm printing out the GET requests
for each file):
2007-07-26 21:08:30.191 server-app[26415] GS: Checking poll results
2007-07-26 21:08:30.191 server-app[26415] GS: calling SSL_read
2007-07-26 21:08:30.191 server-app[26415] GS: done with SSL_read, len
= 145, text = GET /TESTFILE?timestamp=20070726164500 HTTP/1.1
Host: SERVER:8443
Pragma: no-cache
Accept: */*
2007-07-26 21:08:30.191 server-app[26415] GS: calling receiveData
2007-07-26 21:08:30.192 server-app[26415] Starting receiveData
2007-07-26 21:08:30.192 server-app[26415] [CLIENT:39044] GET /
TESTFILE?timestamp=20070726164500 HTTP/1.1
2007-07-26 21:08:30.192 server-app[26415] Calling processRequest:nil
from endHeaders
2007-07-26 21:08:30.192 server-app[26415] Starting processRequest
2007-07-26 21:08:30.193 server-app[26415] Starting processGet
2007-07-26 21:08:30.193 server-app[26415] Removed leading /
2007-07-26 21:08:30.193 server-app[26415] Did safety check
2007-07-26 21:08:30.194 server-app[26415] Computed disk location
2007-07-26 21:08:30.194 server-app[26415] [CLIENT:39044] HTTP/1.1 200 OK
2007-07-26 21:08:30.194 server-app[26415] sendResponseStatusLine:
logged response
2007-07-26 21:08:30.195 server-app[26415] sendString: calling sendData
2007-07-26 21:08:30.195 server-app[26415] sendData: adding object to
sendQueue
2007-07-26 21:08:30.195 server-app[26415] sendData: finished adding
object
2007-07-26 21:08:30.195 server-app[26415] sendData: finished setting
_sendBuffer
2007-07-26 21:08:30.195 server-app[26415] sendString: finished sendData
2007-07-26 21:08:30.195 server-app[26415] sendResponseStatusLine:
sent response
2007-07-26 21:08:30.195 server-app[26415] Sent 200 OK
2007-07-26 21:08:30.196 server-app[26415] Sending response body
2007-07-26 21:08:30.196 server-app[26415] sendString: calling sendData
2007-07-26 21:08:30.196 server-app[26415] sendData: adding object to
sendQueue
2007-07-26 21:08:30.196 server-app[26415] sendData: finished adding
object
2007-07-26 21:08:30.196 server-app[26415] sendData: finished setting
_sendBuffer
2007-07-26 21:08:30.197 server-app[26415] sendString: finished sendData
2007-07-26 21:08:30.197 server-app[26415] sendString: calling sendData
2007-07-26 21:08:30.197 server-app[26415] sendData: adding object to
sendQueue
2007-07-26 21:08:30.197 server-app[26415] sendData: finished adding
object
2007-07-26 21:08:30.197 server-app[26415] sendData: finished setting
_sendBuffer
2007-07-26 21:08:30.197 server-app[26415] sendString: finished sendData
2007-07-26 21:08:30.198 server-app[26415] sendData: adding object to
sendQueue
2007-07-26 21:08:30.198 server-app[26415] sendData: finished adding
object
2007-07-26 21:08:30.198 server-app[26415] sendData: finished setting
_sendBuffer
2007-07-26 21:08:30.198 server-app[26415] Done
2007-07-26 21:08:30.198 server-app[26415] Finished processGet
2007-07-26 21:08:30.198 server-app[26415] Done with processReq from
endHeaders
2007-07-26 21:08:30.199 server-app[26415] GS: done with receiveData
2007-07-26 21:08:30.199 server-app[26415] GS: Got response from
sendDataPending
2007-07-26 21:08:30.199 server-app[26415] GS: Calling poll with
timeout 60000
2007-07-26 21:08:30.199 server-app[26415] GS: Checking poll results
2007-07-26 21:08:30.199 server-app[26415] GS: calling SSL_write on
buffer of length 17
2007-07-26 21:08:30.200 server-app[26415] GS: done with SSL_write
2007-07-26 21:08:30.200 server-app[26415] Called advanceSendBuffer:len
2007-07-26 21:08:30.200 server-app[26415] GS: Got response from
sendDataPending
2007-07-26 21:08:30.200 server-app[26415] GS: Calling poll with
timeout 60000
2007-07-26 21:08:30.200 server-app[26415] GS: Checking poll results
2007-07-26 21:08:30.200 server-app[26415] GS: calling SSL_write on
buffer of length 50
2007-07-26 21:08:30.201 server-app[26415] GS: done with SSL_write
2007-07-26 21:08:30.201 server-app[26415] Called advanceSendBuffer:len
2007-07-26 21:08:30.201 server-app[26415] GS: Got response from
sendDataPending
2007-07-26 21:08:30.201 server-app[26415] GS: Calling poll with
timeout 60000
2007-07-26 21:08:30.201 server-app[26415] GS: Checking poll results
2007-07-26 21:08:30.201 server-app[26415] GS: calling SSL_write on
buffer of length 24
2007-07-26 21:08:30.202 server-app[26415] GS: done with SSL_write
2007-07-26 21:08:30.202 server-app[26415] Called advanceSendBuffer:len
2007-07-26 21:08:30.202 server-app[26415] GS: Got response from
sendDataPending
2007-07-26 21:08:30.202 server-app[26415] GS: Calling poll with
timeout 60000
2007-07-26 21:08:30.202 server-app[26415] GS: Checking poll results
2007-07-26 21:08:30.202 server-app[26415] GS: calling SSL_write on
buffer of length 1281
2007-07-26 21:08:30.203 server-app[26415] GS: done with SSL_write
2007-07-26 21:08:30.203 server-app[26415] Called advanceSendBuffer:len
2007-07-26 21:08:30.203 server-app[26415] GS: Calling poll with
timeout 60000
2007-07-26 21:08:33.086 server-app[26415] GS: Checking poll results
2007-07-26 21:08:33.087 server-app[26415] GS: calling SSL_read
2007-07-26 21:08:33.087 server-app[26415] GS: done with SSL_read, len
= 145, text = GET /TESTFILE?timestamp=20070726165500 HTTP/1.1
The 3-second jump in the fourth- to third-last line is a manual step
in the debugger on the client end- it's stepping to the next GET
request. Normally, this is the point where I see the 50ms delay on
each transmission.
From the tcpdump output, it looks like the server's transmission
from .203 was send over the wire at .290. Then the server goes into
waiting mode for the next request- this is the point where we see the
delay (usually 50ms, not 3s as here). This seems to imply a delay on
the client end, but I confirmed that the client immediately calls
curl_easy_perform at this point- hence, I don't think it's processing
delay, although I may be wrong about this.
If I understand correctly the delay seems to be just after you
wrote your HTTP headers and content body, so this would include
network propagation delay and processing at the far end.
Could the fact that we got two ACKs in this time mean that the server
is waiting for an ACK? Another message in this thread said:
"50 ms is a common standalone ACK timer, so if one had a second or
Nth small send, it might have been waiting (via Nagle) for the
remote's standalone ACK before being transmitted. Some folks like to
simply switch-off nagle, I prefer to try to get folks to send
logically associated data to the transport in one send call."
I did switch off Nagle on the client side, but not the server side.
I'm definitely willing to rethink how I'm sending my data- I'm
basically just relying on the libcurl sending functionality. The
client log shows this as:
* Re-using existing connection! (#0) with host SERVER
* Connected to SERVER (SERVER) port 8443
> GET /TESTFILE?timestamp=20070726164500 HTTP/1.1
Host: SERVER:8443
Pragma: no-cache
Accept: */*
< HTTP/1.1 200 OK
< Content-type: application/x-troff; charset=utf-8
< Content-length: 1281
* Connection #0 to host SERVER left intact
If there is a better way to do this, please let me know! I'm
something of a newbie at client/server code.
Thanks, everyone, for your help so far with this.
--David
______________________________________________________________________
OpenSSL Project http://www.openssl.org
User Support Mailing List openssl-users@openssl.org
Automated List Manager [EMAIL PROTECTED]
