PHP echo causes Apache to reach Timeout, related to output buffering

Question

Context

I have a website that runs on a LAMP architecture.

Basically, all HTML pages are pre-processed into one central php script. The output is only flushed at the very end of this script.

<?php
// PHP builds the HTML response as a string
$controller = new MasterController();
$html = $controller->render();

// Send headers
header('Content-Type: text/html');

// Send HTML response
echo $html;
?>

Server configuration :

# cat /etc/debian_version
6.0.4

# apache2 -v
Server version: Apache/2.2.16 (Debian)
Server built:   Apr  1 2012 06:40:08

# php --version
PHP 5.3.3-7+squeeze17 with Suhosin-Patch (cli) (built: Aug 26 2013 07:26:12)

Issue

I recently discovered that sometimes, the script fails to exit.

In order to track down this issue, I created a Timer class built over microtime(), and adapted my script as follows :

<?php
// Initiate the microtime() timer
$timer = new Timer();

// PHP builds the HTML response as a string
$controller = new MasterController();
$html = $controller->render();

// Send headers
header('Content-Type: text/html');

// Send HTML response
$timer->log('Just before echo\'ing the $html variable');
echo $html;
$timer->log('Just after echo\'ing the $html variable');
?>

Most of the times, the execution will perform nicely :

Abs. (s)  Rel. (s)  Message
   0.000    +0.000  Timer __construct()'ed
...
   0.624    +0.624  Just before echo'ing the $html variable
   0.624    +0.000  Just after echo'ing the $html variable
   0.624    +0.000  Timer __destruct()'ed

But sometimes it will strangely freeze and timeout :

Abs. (s)  Rel. (s)  Message
   0.000    +0.000  Timer __construct()'ed
...
   0.612    +0.612  Just before echo'ing the $html variable
 120.709  +120.097  Timer __destruct()'ed

• Abs. (s) = Absolute time (in seconds) = Time elapsed from the creation of the timer until the current line of log.
• Rel. (s) = Relative time (in seconds) = Time elapsed from the previous line of log until the current line of log.

Analysis

1. The "Timer __destruct()'ed" log line is written when the script ends. In the "freezing" case, the script execution seems to be aborted by the Apache Timeout directive (120 seconds). I verified that no other timeout was involved : setting Apache Timeout to 90 seconds will cause the abortion to occur after 90 seconds. Even PHP's max_execution_time, set to 30 seconds, doesn't prevent the script from reaching the 120 seconds of Apache Timeout.

2. When the failure occurs, the "Just after ..." line doesn't appears in the log, meaning that the echo command doesn't "terminate". I verified later that chunking my $html variable would allow the first few chunks to get out, then the freezing occurs at some "random" chunk. Mostly the 24 ko - 28 ko chunk (for a 4 ko chunk size, or 24 ko - 32 ko if chunk size is 8 ko), but not only.

3. I can't see any recurring pattern in the webpages involved. Huge pages (> 500 ko) are more likely to fail, but do not fail at every request. Small-sized pages (< 80 ko) may fail as well. The failure occurs rarely, compared to the amount of pages delivered by the website.

Buffering

I tried to play on 3 different settings :

• PHP output_buffering directive (currently set to 4096)
• Apache SendBufferSize directive (currently set to 131071)
• Using manual chunk_split() in the PHP script, with a chunk size of 4096 (aligned to the output_buffering value).

All those configs shown improvments (less pages freezing) but I was unable to completely eradicated the issue.

Help ?!

Useful links

http://altroleet.com/blog/?p=54

http://www.binarytides.com/output-buffering-php-apache/

Status

Currently trying with SendBufferSize 1048576, output_buffering Off and no chunks (echo $html;).

Answer 1

Try to measure memory usage of this script and see if there is a pattern

as it looks like echo can't handle this amount of data check this post for methods

https://stackoverflow.com/a/2192689/1384300

also i think it may be related to this old bug

https://bugs.php.net/bug.php?id=18029

here is workaround which I found for this

function echobig($string, $bufferSize = 8192) {
  $splitString = str_split($string, $bufferSize);
  foreach($splitString as $chunk) {
    echo $chunk;
  }
}

and url where I found it

http://wonko.com/post/seeing_poor_performance_using_phps_echo_statement_heres_why