Re: [PHP] Strange slowdowns in PHP
On Mon, Feb 27, 2006 at 05:16:01PM -0500, William Lovaton wrote: > Mmmm... can you elaborate on that please? I kind of have the idea of > what you mean but I don't know how to do it. > > What is exactly garbage collection in the context of a PHP session? I > guess it is when PHP scans every session file to see if there are stale > data or something like that and you can tune the probability of this > process being triggered in the php.ini file. Yeah, i believe that is the GC he is talking about. By default, php will do GC 1% of the requests, the actual rate of GC an how much work it needs to do is predicted by: session.gc_divisor session.gc_probability session.gc_maxlifetime see: http://php.net/manual/en/ini.php > > How would you measure that? is there a way to do that? If you are trying to benchmark the script and log excessive time for a script to execute, i would probably suggest to use the auto_prepend and auto_append directives to include scripts that set begin and end times and log things, vs setting the start time in apache and waiting for php to actually finishing its shutdown process. Curt. -- cat .signature: No such file or directory -- PHP General Mailing List (http://www.php.net/) To unsubscribe, visit: http://www.php.net/unsub.php
Re: [PHP] Strange slowdowns in PHP
Mmmm... can you elaborate on that please? I kind of have the idea of what you mean but I don't know how to do it. What is exactly garbage collection in the context of a PHP session? I guess it is when PHP scans every session file to see if there are stale data or something like that and you can tune the probability of this process being triggered in the php.ini file. How would you measure that? is there a way to do that? Thanks for you insight. -William El lun, 27-02-2006 a las 16:34 -0500, Robert Cummings escribió: > 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. | > `--
Re: [PHP] 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. | `' -- PHP General Mailing List (http://www.php.net/) To unsubscribe, visit: http://www.php.net/unsub.php
[PHP] Strange slowdowns in PHP
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
