Re: Strange slowdowns in PHP

What about session garbage collection? Can you log when that happens and see if it correlates with your problem? Cheers, Rob. On Mon, 2006-02-27 at 16:15, William Lovaton wrote: > 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 -- .------------------------------------------------------------. | InterJinn Application Framework - http://www.interjinn.com | :------------------------------------------------------------: | An application and templating framework for PHP. Boasting | | a powerful, scalable system for accessing system services | | such as forms, properties, sessions, and caches. InterJinn | | also provides an extremely flexible architecture for | | creating re-usable components quickly and easily. | `------------------------------------------------------------'