| Author |
|
oeriksen
Joined: 12 Mar 2013
Posts: 8
Location: Norway
|
 Posted: Wed 13 Mar '13 16:33 Post subject: Delay/pause in mod_rewrite |
 |
|
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
|
| Posted: Thu 14 Mar '13 0:35 Post subject: |
|
|
| 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
|
| Posted: Thu 14 Mar '13 0:57 Post subject: |
|
|
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
|
| Posted: Thu 14 Mar '13 1:10 Post subject: |
|
|
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
|
| Posted: Thu 14 Mar '13 1:20 Post subject: |
|
|
| got to love open source allowing you to do just that! |
|
| Back to top |
|
admin
Site Admin
Joined: 15 Oct 2005
Posts: 692
|
| Posted: Fri 15 Mar '13 9:43 Post subject: |
|
|
| Best to post your issue also at the Dev list. |
|
| Back to top |
|
oeriksen
Joined: 12 Mar 2013
Posts: 8
Location: Norway
|
| Posted: Fri 15 Mar '13 19:37 Post subject: |
|
|
In mod_rewrite.c line 4667 I changed
| Quote: | | if (!prefix_stat(r->filename, r->pool)) { |
to
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: 692
|
| Posted: Fri 15 Mar '13 20:12 Post subject: |
|
|
| Yep the apache dev mailing list. Already pointed a dev to this thread. |
|
| Back to top |
|
covener
Joined: 23 Nov 2008
Posts: 59
|
|
| Back to top |
|
oeriksen
Joined: 12 Mar 2013
Posts: 8
Location: Norway
|
| Posted: Sat 16 Mar '13 2:42 Post subject: |
|
|
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
|
| Posted: Sat 16 Mar '13 3:08 Post subject: |
|
|
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! 
| 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: 3092
Location: Hilversum, NL, EU
|
| Posted: Sat 16 Mar '13 11:05 Post subject: |
|
|
Thanks! for figuring this out.
Steffen |
|
| Back to top |
|
oeriksen
Joined: 12 Mar 2013
Posts: 8
Location: Norway
|
| Posted: Tue 19 Mar '13 23:57 Post subject: |
|
|
| I just hope this will help somebody else one day. |
|
| Back to top |
|
