logo
Apache Lounge
Webmasters

 

About Forum Index Downloads Search Register Log in RSS X


Keep Server Online

If you find the Apache Lounge, the downloads and overall help useful, please express your satisfaction with a donation.

or

Bitcoin

A donation makes a contribution towards the costs, the time and effort that's going in this site and building.

Thank You! Steffen

Your donations will help to keep this site alive and well, and continuing building binaries. Apache Lounge is not sponsored.
Post new topic   Forum Index -> Apache View previous topic :: View next topic
Reply to topic   Topic: Delay/pause in mod_rewrite
Author
oeriksen



Joined: 12 Mar 2013
Posts: 8
Location: Norway

PostPosted: Wed 13 Mar '13 16:33    Post subject: Delay/pause in mod_rewrite Reply with quote

I'm running Apache 2.4.4 Win32 on a Windows 2008 server. When trying to optimize a website I noticed a random reoccurring 2550ms delay in Time To First Byte. A file could have a TTFB of 200ms several times but suddenly it would get 2750ms. This could be a static file (image, html, js) or php. I've measured using ApacheBench (locally and remotely), webpagetest.org and bytecheck.com. After much trial and error I found the problem was with mod_rewrite. Disabling this and everything is fine.

I have setup a blank/new install with only basic config change (Listen, ServerRoot etc) to replicate result without anything else interfering. Following is the rewrite section I add to config.
Code:
<IfModule mod_rewrite.c>
  RewriteEngine on
  RewriteRule (^/Pictures.*)   /$1 [L]
</IfModule>

After Apache has started I execute "ab http://my.example.com/Pictures/Thumbnails/tmb_400X400_FFFFFF_660.jpg" and always get the delay. If I execute again it's normal. If I wait at least 30 seconds I get the delay. Following is a section from error.log with trace8 logging.
Code:
[Tue Mar 12 23:28:56.123519 2013] [rewrite:trace3] [pid 7624:tid 888] mod_rewrite.c(468): [client 69.x.y.90:36279] 69.x.y.90 - - [my.example.com/sid#42c748][rid#26df0d0/initial] applying pattern '(^/Pictures.*)' to uri '/Pictures/Thumbnails/tmb_400X400_FFFFFF_660.jpg'
[Tue Mar 12 23:28:56.123519 2013] [rewrite:trace2] [pid 7624:tid 888] mod_rewrite.c(468): [client 69.x.y.90:36279] 69.x.y.90 - - [my.example.com/sid#42c748][rid#26df0d0/initial] rewrite '/Pictures/Thumbnails/tmb_400X400_FFFFFF_660.jpg' -> '//Pictures/Thumbnails/tmb_400X400_FFFFFF_660.jpg'
[Tue Mar 12 23:28:56.123519 2013] [rewrite:trace2] [pid 7624:tid 888] mod_rewrite.c(468): [client 69.x.y.90:36279] 69.x.y.90 - - [my.example.com/sid#42c748][rid#26df0d0/initial] local path result: //Pictures/Thumbnails/tmb_400X400_FFFFFF_660.jpg
[Tue Mar 12 23:28:58.674665 2013] [rewrite:trace2] [pid 7624:tid 888] mod_rewrite.c(468): [client 69.x.y.90:36279] 69.x.y.90 - - [my.example.com/sid#42c748][rid#26df0d0/initial] prefixed with document_root to D:/WWWDOCS/my.example.com/Pictures/Thumbnails/tmb_400X400_ffffff_660.jpg
[Tue Mar 12 23:28:58.675665 2013] [rewrite:trace1] [pid 7624:tid 888] mod_rewrite.c(468): [client 69.x.y.90:36279] 69.x.y.90 - - [my.example.com/sid#42c748][rid#26df0d0/initial] go-ahead with D:/WWWDOCS/my.example.com/Pictures/Thumbnails/tmb_400X400_ffffff_660.jpg [OK]

As you see from line 3 to line 4 the time skips 2550ms. When the TTFB is normal then the log is identical except time doesn't change from line 3 to line 4. If I delete the rewrite section in config then TTFB is always normal, no matter what.

When I testet on the live server the time for fully loaded increase from 3800-4000ms to 8500-10500ms when mod_rewrite is enabled. And that is about 30 requests (php+css+js+images). So the impact is significant.

What can this be? I'm having a hard time believing it's a bug nobody else have found yet. Isn't mod_rewrite used a lot? I'm running Ubuntu (linux) at home, I'm going to install Apache there and see if I get the same result.

Regards,
Oyvind Eriksen
Back to top
oeriksen



Joined: 12 Mar 2013
Posts: 8
Location: Norway

PostPosted: Thu 14 Mar '13 0:35    Post subject: Reply with quote

I have just tested on Ubuntu with both version 2.2.22 (standard) and 2.4.4 (from source). Neither of these had any problems with mod_rewrite. I testet on a Windows 7 machine I have at home with both version 2.2.24 and 2.4.4 and both of these had the problems with mod_rewrite. So it seems pretty clear to be a Windows specific problem. What can be different from Unix version to Windows version? Is the source code changed before Windows binaries are compiled?
Back to top
glsmith
Moderator


Joined: 16 Oct 2007
Posts: 2268
Location: Sun Diego, USA

PostPosted: Thu 14 Mar '13 0:57    Post subject: Reply with quote

PCRE, APR, APR-Util

On Ubuntu it's usually whatever versions of these your distro maintains on that version of the OS. On Windows, these are not built-in to the OS so there could be differences in them.

httpd -V
from the command line of both will show if there's a difference in APR/APR-Util.

There are other differences in the source because simply Windows ain't Unix. The MPMs are quite different too.

I do not see anything Windows specific in mod_rewrite itself, but it's just a module.

Then there's Windows itself ... who knows.
Back to top
oeriksen



Joined: 12 Mar 2013
Posts: 8
Location: Norway

PostPosted: Thu 14 Mar '13 1:10    Post subject: Reply with quote

I checked the source code for mod_rewrite and found the following between the log messages (where the delay occurs).
Code:
            /* if there is no valid prefix, we call
             * the translator from the core and
             * prefix the filename with document_root
             *
             * NOTICE:
             * We cannot leave out the prefix_stat because
             * - when we always prefix with document_root
             *   then no absolute path can be created, e.g. via
             *   emulating a ScriptAlias directive, etc.
             * - when we always NOT prefix with document_root
             *   then the files under document_root have to
             *   be references directly and document_root
             *   gets never used and will be a dummy parameter -
             *   this is also bad
             *
             * BUT:
             * Under real Unix systems this is no problem,
             * because we only do stat() on the first directory
             * and this gets cached by the kernel for along time!
             */

Don't know if this is relevant but it may be. I'm going to compile my own version of mod_rewrite with more logging to see exactly where the delay occur. And possibly also try to skip prefix_stat and see if that helps (just to test).
Back to top
glsmith
Moderator


Joined: 16 Oct 2007
Posts: 2268
Location: Sun Diego, USA

PostPosted: Thu 14 Mar '13 1:20    Post subject: Reply with quote

got to love open source allowing you to do just that!
Back to top
admin
Site Admin


Joined: 15 Oct 2005
Posts: 677

PostPosted: Fri 15 Mar '13 9:43    Post subject: Reply with quote

Best to post your issue also at the Dev list.
Back to top
oeriksen



Joined: 12 Mar 2013
Posts: 8
Location: Norway

PostPosted: Fri 15 Mar '13 19:37    Post subject: Reply with quote

In mod_rewrite.c line 4667 I changed
Quote:
if (!prefix_stat(r->filename, r->pool)) {

to
Quote:
if (1) {

This forces it to always prefix with document_root without checking for absolute path.
It seems to have just the effect I suspected, the delay is gone. I will test some more and see if I can trace the root of the problem.

admin: you mean the apache dev mailing list?
Back to top
admin
Site Admin


Joined: 15 Oct 2005
Posts: 677

PostPosted: Fri 15 Mar '13 20:12    Post subject: Reply with quote

Yep the apache dev mailing list. Already pointed a dev to this thread.
Back to top
covener



Joined: 23 Nov 2008
Posts: 55

PostPosted: Sat 16 Mar '13 1:38    Post subject: Reply with quote

this thread reminded me of a possibly related issue:

https://issues.apache.org/bugzilla/show_bug.cgi?id=45464
Back to top
oeriksen



Joined: 12 Mar 2013
Posts: 8
Location: Norway

PostPosted: Sat 16 Mar '13 2:42    Post subject: Reply with quote

That bug looked very similar yes.

I added a little more logging in prefix_stat() in mod_rewrite.c and found that the following (line 857) is what causes the delay.
Quote:
rv = apr_filepath_root(&root, &curpath, APR_FILEPATH_TRUENAME, pool);
Back to top
oeriksen



Joined: 12 Mar 2013
Posts: 8
Location: Norway

PostPosted: Sat 16 Mar '13 3:08    Post subject: Reply with quote

I suddenly realized something. It's actually sort of an configuration error. Many of the rewrite rules on my site, including the one I have been testing with, is of the following format.
Quote:
RewriteRule (^/Pictures.*) /$1 [L]

This will make /Pictures/Folder/image.jpg to be rewritten to //Pictures/Folder/image.jpg (see the extra slash?). This is (probably) checked as a possible windows share (\\server\share) and has a timeout. Windows must be caching/remembering that //Pictures/ isn't a server for some time (30 seconds?). I changed the rewrite rule without the extra slash and delay is GONE! Smile
Quote:
RewriteRule (^/Pictures.*) $1 [L]

I haven't made the rewrite rules myself, it's part of a complete shopping cart system, delivered by a CRM system the company is using.
But this is an easy fault to do and will cause quite a bit of delay on Windows systems.
Back to top
Steffen
Moderator


Joined: 15 Oct 2005
Posts: 3049
Location: Hilversum, NL, EU

PostPosted: Sat 16 Mar '13 11:05    Post subject: Reply with quote

Thanks! for figuring this out.

Steffen
Back to top
oeriksen



Joined: 12 Mar 2013
Posts: 8
Location: Norway

PostPosted: Tue 19 Mar '13 23:57    Post subject: Reply with quote

I just hope this will help somebody else one day.
Back to top


Reply to topic   Topic: Delay/pause in mod_rewrite View previous topic :: View next topic
Post new topic   Forum Index -> Apache