Ticket #1338 (new defect)

Opened 10 months ago

Last modified 6 months ago

Very slow 304 responses, introduced in 1949.

Reported by: zlib Assigned to: jan
Priority: high Milestone: 1.5.0
Component: core Version: 1.5.x-svn
Severity: critical Keywords: slow 304
Cc: lighty-ticket1338@codef0x.org, stepancheg Blocking:
Need Feedback: 0

Description

Hi,

I just upgraded from change-set 1857 to 1981 to discover images were taking a very long time to load.

These images were going through my mod_proxy_core setup. They appear to load quickly if the browser does not already have them cached, however when a 304 response is sent from the server, that's when it goes slow.

I also noticed that the log file shows 5 bytes being sent with the 304 response whereas with change-set 1857, zero byes are sent with the request.

This only occurs with images sent through mod_proxy_core. Direct requests (bypass proxy) work just fine so I assume the problem is definitely occurring at mod_proxy_core.

Thanks.

Attachments

lighttpd.trace (14.5 kB) - added by zlib on 09/09/2007 10:01:50 AM.
lighttpd.2.trace (13.1 kB) - added by zlib on 09/09/2007 02:31:15 PM.
More clear

Change History

09/09/2007 09:00:57 AM changed by jan

Please attach a strace (see wiki -> how to report a bug) showing the behaviour.

09/09/2007 10:01:50 AM changed by zlib

  • attachment lighttpd.trace added.

09/09/2007 10:08:09 AM changed by zlib

I have attached a strace of me requesting the file /css/style.css?2 which takes about 5 seconds to load.

As this is running on my development machine, I have lighty configured to run as serveral servers in one by the use of $SERVERsocket?. So when proxy requests come in, its actually serving from the same server process.

09/09/2007 02:31:15 PM changed by zlib

  • attachment lighttpd.2.trace added.

More clear

09/09/2007 02:35:58 PM changed by zlib

I've now broken up my setup into separate processes so lighty isn't running everything in one go. Hopefully this is has given you a more clear strace.

From watching the strace as I request the file, the following seems to happen:

- Client request /img/logo1.gif - Lighty forwards request through mod_proxy_core to another server - That server immediately responds with 304 status - Lighty does nothing for 4 seconds before returning 304 to the client

Thanks.

11/09/2007 03:15:10 PM changed by zlib

  • priority changed from normal to high.
  • component changed from mod_proxy_backend_http to core.
  • severity changed from major to critical.
  • summary changed from Very slow 304 responses [1981] to Very slow 304 responses, introduced in 1949..

I've done some testing and found the problem to occur after the changes made in changeset 1949.

When requesting a file through my mod_proxy_core setup an additional header is returned, "Transfer-Encoding: chunked" along with the request hanging for about 5 seconds.

When requesting a file directly from the backend server and not via the proxy, it is returned instantly without the "Transfer-Encoding: chunked" header.

Here is the problem occuring after changeset 1949 and requesting via the load balanced proxy (bug version) 

curl -v -H "If-Modified-Since: Sun, 01 Jan 2036 00:00:02 GMT" http://alpha.mingleville.com/robots.txt
* About to connect() to alpha.mingleville.com port 80
*   Trying 10.0.0.31... * connected
* Connected to alpha.mingleville.com (10.0.0.31) port 80
> GET /robots.txt HTTP/1.1
User-Agent: curl/7.12.1 (i686-redhat-linux-gnu) libcurl/7.12.1 OpenSSL/0.9.7a zlib/1.2.1.2 libidn/0.5.6
Host: alpha.mingleville.com
Pragma: no-cache
Accept: */*
If-Modified-Since: Sun, 01 Jan 2036 00:00:02 GMT

< HTTP/1.1 304 Not Modified
< Content-Type: text/plain
< ETag: "61981870"
< Accept-Ranges: bytes
< Last-Modified: Fri, 09 Nov 2007 12:00:38 GMT
< Date: Fri, 09 Nov 2007 14:48:49 GMT
< Server: lighttpd
< Transfer-Encoding: chunked
* Connection #0 to host alpha.mingleville.com left intact
* Closing connection #0

Here is the output when using changeset 1948 or 2019 with the block of code removed from response.c (working version) 

curl -v -H "If-Modified-Since: Sun, 01 Jan 2036 00:00:02 GMT" http://alpha.mingleville.com/robots.txt
* About to connect() to alpha.mingleville.com port 80
*   Trying 10.0.0.31... * connected
* Connected to alpha.mingleville.com (10.0.0.31) port 80
> GET /robots.txt HTTP/1.1
User-Agent: curl/7.12.1 (i686-redhat-linux-gnu) libcurl/7.12.1 OpenSSL/0.9.7a zlib/1.2.1.2 libidn/0.5.6
Host: alpha.mingleville.com
Pragma: no-cache
Accept: */*
If-Modified-Since: Sun, 01 Jan 2036 00:00:02 GMT

< HTTP/1.1 304 Not Modified
< Content-Type: text/plain
< ETag: "61981870"
< Accept-Ranges: bytes
< Last-Modified: Fri, 09 Nov 2007 12:00:38 GMT
< Date: Fri, 09 Nov 2007 14:23:11 GMT
< Server: lighttpd
< Content-Length: 0
* Connection #0 to host alpha.mingleville.com left intact
* Closing connection #0

11/27/2007 06:26:29 PM changed by anonymous

  • cc set to lighty-ticket1338@codef0x.org.

12/26/2007 04:29:13 PM changed by stepancheg

  • cc changed from lighty-ticket1338@codef0x.org to lighty-ticket1338@codef0x.org, stepancheg.

#1178

Add/Change #1338 (Very slow 304 responses, introduced in 1949.)




Change Properties