Troubleshooting Delays (several seconds) in PHP or WordPress

My custom error pages were running extremely slowly, taking about 60 seconds “waiting” and then displaying all at once.

The hosting company said they don’t have any performance profiling software. “Have you tried renaming your .htaccess file, you have a lot of redirects, that’s probably what’s causing it.” (No, of course I’d already looked into that. Dumb hosting tech support advice.)

Well, then “try checking your error logs”. No, I’ve already installed code in my WordPress wp-config.php, and in my error pages, to log extra PHP errors. No errors at all related to this; just some undeclared variables in one WordPress plugin. See my page on Error Information Only For You.

I have been a PHP programmer for years. I know that there are debugging tools, and there are tools to measure where exactly in a program are the most resources being used, or where is the program taking the most time.

I found Benchmark, a “framework to benchmark PHP scripts or function calls”. On some web hosts, you install Benchmark via cPanel under “PHP PEAR Packages”; on others you install it yourself with SSH commands; or your hosting company may not have any way for you to install it. (Even if you think you won’t ever use SSH, don’t even know what that is, “SSH included” is a good indicator for a good hosting company, and so is “PHP Pear Packages”.)

Testing your own programs

First put in some code so only I can generate testing results, as some of the testing methods (especially Iterate) can use many resources. You also may want to display testing items in the browser, only for you. There are also some required initialization lines for Benchmark. Much of this section of code is a long comment, giving examples of Benchmark calls.

if ( in_array($ip, $myipaddress ) || in_array($forwardedfor, $myipaddress) ) {
	echo "<p>Docroot $docroot</p>";
	$onlyMe = true;
} else {
	$onlyMe = false;
}
if ($onlyMe) { 
/* http://pear.php.net/package/Benchmark/docs/latest/ 
Install via cPanel PHP PEAR Packages 
*/

/* must add to path if haven't already */
	ini_set("include_path", '/home/USERNAME/php:' . ini_get("include_path") );

/* some examples of Benchmark calls
	require_once 'Benchmark/Iterate.php';
	$benchmark = new \Benchmark_Iterate;
	$benchmark->run(10, 'err->update_errorlog', 'test');
	$result = $benchmark->get();
	$benchmark->display(true);
	
	require_once 'Benchmark/Profiler.php';
	$benchmark = new \Benchmark_Profiler(TRUE);
	$benchmark->enterSection('update_errorlog');
	$err->update_errorlog();
	$benchmark->leaveSection('update_errorlog');
	//Returns formatted informations
	$benchmark->display(true);
end of examples */

	require_once 'Benchmark/Profiler.php';
	$benchmark = new \Benchmark_Profiler(TRUE);
}

Defining Sections of Your Code To Test

Now you select parts of your code where you want to test the performance, especially separating out places that you think might be too slow.

You use “enterSection” and “leaveSection” commands, and give your own description of the section of code. This short description will appear in the chart of results.

if ($onlyMe) { 
	$benchmark->enterSection('ini set');
}

/* code for initialization  */

if ($onlyMe) {
 	$benchmark->leaveSection('ini set');
	$benchmark->enterSection('which log file');
}

/* setting which log file to use */

if ($onlyMe) {
 	$benchmark->leaveSection('which log file');
	$benchmark->enterSection('define functions');
}

/* code for defining functions */

if ($onlyMe) { 
	$benchmark->leaveSection('define functions');
	$benchmark->enterSection('gather error info');
}

/* code for gathering error info */

if ($onlyMe) { 
	$benchmark->leaveSection('gather error info');
	$benchmark->enterSection('shutdown function');
}

/* code for defining shutdown function */

if ($onlyMe) { 
	$benchmark->leaveSection('shutdown function');
	$benchmark->enterSection('get POST content');
}

You can define as many sections as you want. However, I suggest beginning with only a few, and narrow down the section of code that testing shows is taking the longest. In this case, it was inside ‘get POST content’ so I split it into 3 sections for further testing.

if ($onlyMe) { 
	$benchmark->leaveSection('get POST content');
	$benchmark->enterSection('get POST content 2');
}

$junk = file_get_contents('php://input'); /* the POST content */

if ($onlyMe) { 
	$benchmark->leaveSection('get POST content 2');
	$benchmark->enterSection('get POST content 3');
}

I never would have guessed it, but turns out the problem was with php://stdin… aren’t those supposed to be automatically enabled? Well, not on this server. Perhaps they are opening php://stdin for SSH but leaving php://stdin not opened for web pages, since it is so rarely used in web pages?

/* this file_get_contents() delays 60 seconds, found with Benchmark */
$junk = file_get_contents('php://stdin'); /* the POST content */

parse_str($junk, $post_vars);
$posts = implode_with_key($post_vars, $inglue = '-->', $outglue = "\n");

if ($onlyMe) { 
	$benchmark->leaveSection('get POST content 3');
	$benchmark->enterSection('rest of file before update');
}

/* code for rest of file */

PHP Benchmark Profile showing error with get-post-content 2016103110

Results of Testing

if ($onlyMe) { 
	$benchmark->leaveSection('update_errorlog');
	
	//Returns formatted information
	$benchmark->display(true);
} else {
	$err->update_errorlog();
}

The results are numbers that are hard to read; some people may never have seen “scientific notation”, with numbers displayed always with a single digit left of the decimal point, and a power-of-ten exponent. All you need to really know is any number ending in “E-5” or “E-6” is a very small number.

The problem will likely be a number between “E-1” (multiply by 0.1) to “E+1” (multiply by 10). “E0” isn’t shown (multiply by 1).

From the top line in the image, 3.7193 E-5 would be written in “standard” notation as 0.000037193

From the highlighted line in the image, something in the “Get POST content” section of code is taking a full 60 seconds. (Happens to match the 60-second timeout tech support says is set for some things in PHP.)

Add a few more enterSection and leaveSection profiling statements in the slow portion of your code, to narrow down what specifically the problem is, down to the single line of code in this case.

Fixing the Problem

Now that I have identified the problem, that tech support couldn’t identify, and that I wouldn’t have guessed, time to search for a solution to the problem.

In this case, there are two likely explanations. 1) One of the standard input streams was waiting for 60 seconds for something to be typed in, and then timing out, or 2) the stream was never opened, and the function call timed out.

/* what seems to fix the problem, declaring the STDIN before attempt to use it, though I'd thought it was always declared */

if (!defined('STDIN')) {	/* not always defined, when PHP called by web browser; define to stop error warnings */
	$stdin = fopen('php://stdin', 'r');
	define('STDIN', $stdin);
}

This might be useful for reading STDIN from command line versions of PHP. I haven’t yet tested it.

if (php_sapi_name() == 'cli' || php_sapi_name() == 'cli_server') {
	$sapi = 'command line';
	echo '<code>'; print_r($_SERVER); echo '</code>';  /* pre looks better than code, but my PHP display plugin uses pre */
} else { $sapi = 'not command line'; }

if (defined('STDIN')) { /* STDIN is available */ }

$junk = file_get_contents('php://input'); /* the actual POST content */
if (empty($junk) && $sapi == 'command line') {
	/* Apache uses php://input, CLI uses php://stdin */
	/* not tested on IIS server, might get 60 second timeout waiting for user input if isn't any */
	
	/* stream_set_blocking(STDIN, 0);
	stream_set_timeout(STDIN, 2);
	*/
	
	/* this doesn't work, can't have string parameter -- 
        stream_set_blocking('php://stdin', 0);
	stream_set_timeout('php://stdin', 2);
	should be a "valid path" not a string -- 
	$junk = file_get_contents($stdin);
	*/
	
	/* this file_get_contents() delays 60 seconds, found with Benchmark */
	$junk = file_get_contents('php://stdin'); /* the POST content */
}

/* check if this works for reading STDIN from PHP-CLI */
$ctx = stream_context_create(array(
	'http' => array(
		'timeout' => 1
		)
	)
);
$junk = file_get_contents('php://stdin', 0, $ctx); 

Other Resources

https://gregheo.com/blog/benchmarking-php/ has clear examples of using Benchmark.

http://pear.php.net/package/Benchmark/docs/1.2.9/elementindex.html for the main Benchmark documentation

Save

Save


by

Comments

Leave a Reply

This site uses Akismet to reduce spam. Learn how your comment data is processed.