Hi there, I just setted up some changes to the Apache configuration and made some programming in PHP to log a request (and information about that request) when it is taking a lot of time to finish (let's say > 20 secs). In the logs, there have been lots of useful information and I already improved the performance on several pages, specially related to database queries. But from time to time there are pages in the log that shouldn't be slow but still they take 20 or 30 secs to complete. The strategy I used is the following: 1. Configure Apache to register the request time in the request headers RequestHeader set requestTime %t 2. Create a function an register it with register_shutdown_function() so it is executed after PHP ends the execution of every script. 3. This function will take the requestTime and calculate the difference with the current time (time stamp). 4. If the difference (execution time) is less than 20 seconds it exits normally, else, it logs the information about this request in a file. 5. The registered information includes: $_REQUEST data and $_SESSION data at the time of execution. And finally a profile of some critical functions. This functions are often the ones that goes to the database and they are likely to be slow. The page I am talking about doesn't execute any database query. It just generates an image from the data that is stored in the session. I however, profile some function that are not database queries but they are the only "critical" path in the script. Looking at the log I get the following information: - Execution time: 29.3 secs - Request started at: 11:08:06 AM - Request ended at: 11:08:35 AM - The functions that got executed were (time, class::method, duration): - 11:08:06, GraficoMaterno::alturaUterina, 0.009499 - 11:08:06, GraficoAlturaUterina::session_start, 0.001259 - 11:08:06, GraficoAlturaUterina::session_write_close, 0.001613 - 11:08:06, GraficoAlturaUterina::sendImage, 0.029186 The last record in the profile (GraficoAlturaUterina::sendImage) corresponds to the last couple of lines of code in the script which are: imagepng($image); imagedestroy($image); As you can see they took only 0.029186 seconds which is very fast. the other thing that you can see in the profile is that the last line of code got executed exactly in the very same second in which the request started. This means that the script is very fast and that something is taking a lot of time after the last line of execution. Note that I open and close the user session to update some data in a safe manner that might be being accessed at the same time by other apache processes. And as you can see it is very fast too... that was the only suspect I had. :( Finally, I don't think this is a problem of the function that logs the execution time and that is executed automatically at shutdown. I was seeing the sporadic slowdown even before implementing this instrumentation and the function implementation is so simple that it is very unlikely that the delay is in there. For further information I am using PHP 4.3.11 and Apache 2, all of them are official packages from a Fedora Core 3 system with the latest updates. Is there a known bug in PHP that might be causing this sporadic slowdowns? In general our web app is very fast but this are the corner cases. Any ideas about this? Thanks in advance, -William -- PHP General Mailing List (http://www.php.net/) To unsubscribe, visit: http://www.php.net/unsub.php
