cooking, programming and everyday life xrado

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.

08:58, Sunday, July 18, 2010 Matjaž, from Solkan
Is it possible to locate the exact (slow) PHP script or you are limited only to $_SERVER['REQUEST_URI']?

...as i said, profiling is for development process. Php slow log is only useful for global overview. Otherwise, every php include would need a timer and still... what do you get if you know that something is slow in 10k lines of php include...

COMMENTS ARE DISABLED