PHP script occasionally waits 20-30 minutes to start

Question

I have a PHP script on my server that, primarily, takes files from an upload and moves them into place. It usually works fine, but occasionally, the script won't start for 20-30 minutes. The entire uploaded files (roughly 0.5 MB) will be sitting in the tmp folder during the wait, so it seems like the data transfer is complete. Here is an excerpt from the Apache access log indicating a POST to the script (from an Android app)...

[29/Nov/2011:11:21:55 -0500] "POST /submit.php HTTP/1.1" 200 288 "-" "Apache-HttpClient/UNAVAILABLE (java 1.4)"

However, this entry doesn't show up in the access log until 11:43 or so, surrounded by other page requests from 11:43:42 and 12:00:02. This leads me to believe the entry doesn't get written until the script executes, but it is written with the time of submission. Here's the error log, where I'm writing events from the script...

[Tue Nov 29 11:43:19 2011] Script started: Nov 29, 2011 11:43:19
[Tue Nov 29 11:43:19 2011] Audio file provided
[Tue Nov 29 11:43:19 2011] Timestamp provided
[Tue Nov 29 11:43:19 2011] Defaults set
[Tue Nov 29 11:43:19 2011] Connected to database
[Tue Nov 29 11:43:19 2011] Database selected
[Tue Nov 29 11:43:19 2011] Query successful
[Tue Nov 29 11:43:19 2011] 551: ID set
[Tue Nov 29 11:43:19 2011] 551: Audio file moved
[Tue Nov 29 11:43:19 2011] 551: Algorithm succeeded
[Tue Nov 29 11:43:19 2011] 551: Algorithm query succeeded
[Tue Nov 29 11:43:19 2011] 551: Photo type identified
[Tue Nov 29 11:43:20 2011] 551: Photo and thumbnail saved
[Tue Nov 29 11:43:20 2011] 551: Cache cleared
[Tue Nov 29 11:43:20 2011] Script finished: Nov 29, 2011 11:43:20

Any idea what would cause a PHP script to not execute for so long, or what kind of logging I should put in place to find out? The server is running Ubuntu 10.04, Apache 2.2.14, and PHP 5.3.2.

Answer 1

You're absolutely correct about the way Apache writes to the log file. The timestamp is set when the child accepted the connection but isn't written to the log file until after the response is sent. This can result in the timestamps being completely out of order in the log file.

The logs from the script itself show that it didn't start running until 22 minutes after the initial connection was made meaning this is an Apache thing and not a PHP thing.

My first guess would be that the upload of the data was taking 20 minutes. 0.5MB wouldn't normally take that long and you said that the whole file appeared to be there for the whole 20 minutes so this may not be our problem.

The next guess is an incomplete upload or a complete upload with no indication that it has completed.

If the Android App is not setting or is incorrectly setting the Content-Length: header I have no idea how Apache would know when to start processing the data.

If the Android user went out of signal range the TCP connection could stay open for quite some time.

The best bet for trying to get a closer look at the timings involved would be to run a tcpdump on your server and look at exactly when the different parts of the request arrived. I hope it's not a particularly busy server. Obviously, the more you can limit this to just the traffic you want the better. make sure to use the -w option so that once you know which IP address caused the problem you can re-read the file and filter out only that IP address's traffic.