Wednesday, July 14, 2010
php slow log
A few days ago a friend called me, asking me how could he find the slowest PHP scripts on its server? ..and didn't think of anything. Of course there are tools like xdebug, but they are only useful in development. If you have a server with hundred websites and you are trying to find out what it taking the most of your cpu time, you will probably need something like mysql slow query log.
I remembered that php.ini has auto_prepend_file and auto_append_file setting, and that can help me wrap every php request with the timer. I made two simple scripts that wont add much extra overhead. It works exactly as mysql slow log. You just set up the SLOW_LOG_TIME and SLOW_LOG_FILE destination. All php requests that take more than SLOW_LOG_TIME will be logged.
php.ini
auto_prepend_file = "/path_to/before.php" auto_append_file = "/path_to/after.php"
before.php
<?php define('SLOW_LOG_START',microtime(TRUE));
after.php
<?php // Settings define('SLOW_LOG_TIME', 0.5); // (sec) define('SLOW_LOG_FILE', '/tmp/php_slow.log'); // Logging define('SLOW_LOG_END', microtime(TRUE)); $time = SLOW_LOG_END - SLOW_LOG_START; if ($time > SLOW_LOG_TIME) { $log = date('Y-m-d H:i:s')."\t".round($time,3)."\t".$_SERVER['SERVER_NAME'].$_SERVER['REQUEST_URI']."\n"; file_put_contents(SLOW_LOG_FILE, $log, FILE_APPEND); }sample output with SLOW_LOG_TIME set to 0.1 sec ( on my home server P4 Celeron 2Ghz, 1Gb Ram )
2010-07-08 23:15:19 0.178 xrado.hopto.org/post/baked-lasagna-and-potatoes-kebab-style-seitan 2010-07-08 23:16:32 0.115 xrado.hopto.org/post/extract-emails 2010-07-08 23:16:34 0.13 xrado.hopto.org/ 2010-07-08 23:16:38 0.121 xrado.hopto.org/post/going-freelance ...
Actually this wont tell you which are the slowest script, but you'll get the list of PHP requests that take the most processing time. That will give you the clue where to start looking.
Final notes:
- do not set SLOW_LOG_TIME too low, otherwise your log will be screaming, your server too, depending on number of requests you get
- check syntax in before.php and after.php, any error can break all your sites
- remove auto_prepend_file and auto_append_file whey you are done, otherwise logs can go big and you don't need extra disk load
It will be nice to see your timings before and after the optimization.