Weird rewrite problem - initial delay

I'm working on a photography portfolio site. One page shows a bunch of thumbnails and one full-size image. Clicking on a thumbnail displays the full-size version of that image. I have been doing this with page refreshes but have decided to add Ajax capability.

The Ajax Javascript issues a GET with a URL something along the lines of:

http://www.example.com/folioAjaxSvr.php?pm=imgdata&pdir=portfolio&img=something.jpg&dir=somedir

The folioAjaxSvr.php script spits back some xml. And this all works fine.

Except ... if the site in question also hosts a Wordpress blog. This means the .htaccess file contains the following lines:

# BEGIN WordPress
RewriteCond %{REQUEST_FILENAME} !-f
RewriteCond %{REQUEST_FILENAME} !-d
RewriteRule . /index.php [L]
# END WordPress

Now, as far as I can see, this should not cause a problem, because the !-f condition should come into play - after all, I'm requesting an actual file. But what happens is that, while the Ajax stuff still works, it takes a lo-o-o-ng time for the xml to be sent back - up to 20 seconds. If I click on another thumbnail, I get a shorter delay, but still fairly long, maybe 7 seconds (this is all happening across a LAN by the way, not the interweb). After that, the response is normal - unless I refresh the page, whereupon I get the initial delays again.

I've give the site plenty of memory (32M) for PHP scripts in php.ini.

If I comment-out the WordPress rules, no problems, so these rules are affecting the response somehow.

The Apache logs show no errors.

The fact that the delay reduces the second time and is gone by the third time suggests cacheing at work somewhere, but I've no idea where.

I tried doing something slightly different. I changed the URL sent by the Ajax script to this form:

http://www.example.com/folioAjaxSvr/imgdata/portfolio/something.jpg/somedir

And added this rule to .htaccess BEFORE the WordPress stuff:

RewriteRule ^folioAjaxSvr/imgdata/(.*)/(.*)/(.*)$ portfolioAjaxSvr.php?pm=imgdata&pdir=$1&img=$2&dir=$3 [L]

Still the same problem. Again, commenting-out the WordPress stuff makes the problem disappear even though, as I understand it, that [L] flag means the .htaccess script should stop there and never get to the WordPress rules.

Huh?

This might be some screwy problem with my own server, but I don't want to go through the process of uploading all this to the live server and find it's the same problem there.

I'd appreciate any suggestions as to where I start looking.

 

That sure is a weird one.

I'd start by ruling out common causes of slowness - particularly ones that have caches - such as PHP by putting microtime() stamps at the start and end of the PHP script. This is just to make absolutely sure that it's the rewrite causing the problem (and because it's fairly easy)

Next, you can turn on the RewriteLog and set it to RewriteLogLevel 3. (You definitely don't want to do this on a production server...)

The RewriteLog contains masses of information but in particular it will show you every regex it considered and in what order before discarding them. I think it has timestamps too so you should be able to see how long each one was taking.

I also have a hunch about the -f rule. This will involve disk access and if you are having any slowness with your disks (beyond the normal slow speed that disks run at) then that rule could cause a lot of slowness.

Let us know what you find.

 

Okay, so I put microtime() calls in at the start and end of my folioAjaxSvr.php script and put the numbers in the XML returned by the script. The numbers you see in parentheses are the times reported by Firebug for the script to repond to the GET call from the browser. These two calls followed a page refresh. All subsequent calls were similar to the second, in terms of time:

first Ajax call: (9761ms)
<start>0.76788300 1205945899</start>
<end>0.80599500 1205945899</end>

2nd: (62ms)
<start>0.41537200 1205945953</start>
<end>0.45314000 1205945953</end>

Then I did a page refresh and made three more calls:

(18705ms)
<start>0.66162100 1205946323</start>
<end>0.69934200 1205946323</end>

(61ms)
<start>0.00177100 1205946354</start>
<end>0.03993300 1205946354</end>

(62ms)
<start>0.15698400 1205946388</start>
<end>0.19507000 1205946388</end>

I'd also invoked the RewriteLog for that virtual host, in the vhosts.d/server.conf file. I saw a bunch of activity in the subsequent log, but all seemed to be related to the fact that the page was looking for a favicon.ico file that wasn't there. To simplify the log, I dumped a favicon file in the root dir, ran the above tests and guess what ... nothing logged. No log file. The log seems to have stopped working, so I'm still looking into that...

This was all done using the first setup, with the folioAjaxSvr.php?pm=imgdata&... type of URL. Just to double-check, I commented-out the WordPress rules, shut down the browser (so no chance of any browser cache skewing results, though I have Firefox's cache turned off anyway).

first call: (60ms)
<start>0.55976800 1205946738</start>
<end>0.59785400 1205946738</end>

2nd: (65ms)
<start>0.02778600 1205946764</start>
<end>0.06573200 1205946764</end>

So, I'm stumped. I commented out rewrite rules that weren't being used anyway, and it speeded up the first call.

So, I switched to using the other form of URL - the type that needs rewriting. Turned on the rewrite rule (but still with the WordPress rules commented-out), refreshed the page, made the first Ajax call and:

(62ms)
<start>0.22910400 1205946954</start>
<end>0.26743100 1205946954</end>

Uncommented the WordPress rules:

(18097ms)
<start>0.73226600 1205947703</start>
<end>0.76992800 1205947703</end>

(62ms)
<start>0.40967500 1205947731</start>
<end>0.44715400 1205947731</end>

I think I need to go have a lie down. Then I'll see if I can work out why RewriteLog only worked the once (yes, I restarted Apache). I tried including the rules in .htaccess but Apache told me that isn't allowed.