High memory peak consumption
Closed this issue · 10 comments
Alexey, hello!
In our projects we use the Blitz template engine and we ran into an unexpectedly high memory consumption when using the parse() method:
$template =<<<'EOL'
Some {{ $text }} text
EOL;
$t = new Blitz();
$t->load($template);
Timer::start('debug', 'fetch');
$text = str_repeat('x', 1024 * 1024 * 22);
Timer::stop();
Timer::start('debug', 'parse');
$t->parse(array(
'text' => $text
));
Timer::stop();
Timer::start('debug', 'replace');
$template = str_replace('{{ $text }}', $text, $template);
Timer::stop();
foreach (Timer::dump() as $timer) {
echo $timer['namespace'] . '::' . $timer['operation'] . "\n";
echo ' Time: ' . $timer['microtime_diff'] . "\n";
echo ' Memory: ' . $timer['memory_start'] . ' -> ' . $timer['memory_stop'] . ' (' . $timer['memory_diff'] . ')' . "\n";
echo ' Max Memory: ' . $timer['memory_peak_stop'] . "\n";
}The above script produces the following results:
PHP 5.3
SUMMARY debug: 3 operation(s) using 90186504 bytes per 0.111985 seconds
------------------------------------------------------------------------------------------------
| Timer | Memory Peak | Memory Fixed | Memory Usage | Operation | #
------------------------------------------------------------------------------------------------
| 0.019335 | 24169864 | 24162376 | 23077440 | fetch | 1
| 0.056742 | 114349856 | 47233616 | 90186504 | parse | 2
| 0.035908 | 114349856 | 70303904 | 23069784 | replace | 3
PHP 5.6
SUMMARY debug: 3 operation(s) using 67118256 bytes per 0.092410 seconds
------------------------------------------------------------------------------------------------
| Timer | Memory Peak | Memory Fixed | Memory Usage | Operation | #
------------------------------------------------------------------------------------------------
| 0.017415 | 23545192 | 23537496 | 23077920 | fetch | 1
| 0.038294 | 90656888 | 23540272 | 67118256 | parse | 2
| 0.036701 | 90656888 | 46610512 | 23069872 | replace | 3
PHP 7.0
SUMMARY debug: 3 operation(s) using 90191360 bytes per 0.096717 seconds
------------------------------------------------------------------------------------------------
| Timer | Memory Peak | Memory Fixed | Memory Usage | Operation | #
------------------------------------------------------------------------------------------------
| 0.018029 | 23433792 | 23434144 | 23073552 | fetch | 1
| 0.063715 | 113625880 | 46508776 | 90191360 | parse | 2
| 0.014973 | 113625880 | 69582304 | 23073528 | replace | 3
We are concerned about peak memory consumption.
Out system configuration:
System | FreeBSD 9.0-RELEASE-p4 FreeBSD 9.0-RELEASE-p4
/usr/obj/usr/src/sys/KERNEL20121021740 amd64
-- | --
Build Date | Jul 22 2016 15:10:06
Configure Command | './configure' '--prefix=/usr/local/php-7.0.9' '--with-config-file-scan-dir=/usr/local/php-7.0.9/etc/php' '--with-config-file-path=/usr/local/php-7.0.9/etc' '--with-layout=GNU' '--with-fpm-user=www' '--with-fpm-group=www' '--program-prefix=' '--disable-all' '--disable-debug' '--disable-ipv6' '--enable-ctype' '--enable-dom' '--enable-fileinfo' '--enable-filter' '--enable-fpm' '--enable-hash' '--enable-json' '--enable-libxml' '--enable-mbstring' '--enable-mysqlnd' '--enable-pcntl' '--enable-phar' '--enable-pdo' '--enable-opcache' '--enable-session' '--enable-simplexml' '--enable-soap' '--enable-tokenizer' '--enable-xml' '--enable-xmlreader' '--enable-xmlwriter' '--enable-zip' '--with-bz2' '--with-curl' '--with-freetype-dir' '--with-gd' '--with-iconv=/usr/local' '--with-jpeg-dir' '--with-libxml-dir=/usr/local' '--with-mcrypt' '--with-mhash' '--with-mysqli' '--with-openssl' '--with-pcre-regex' '--with-pdo-mysql' '--with-pdo-sqlite' '--with-sqlite3' '--with-zlib-dir=/usr' 'CFLAGS=-O2 '-pipe' '-fstack-protector' '-fno-strict-aliasing'' 'CPP=cpp'
Server API | FPM/FastCGI
Virtual Directory Support | disabled
Configuration File (php.ini) Path | /usr/local/php-7.0.9/etc
Loaded Configuration File | /usr/local/php-7.0.9/etc/php.ini
Scan this dir for additional .ini files | /usr/local/php-7.0.9/etc/php
Additional .ini files parsed | /usr/local/php-7.0.9/etc/php/blitz.ini, /usr/local/php-7.0.9/etc/php/memcache.ini, /usr/local/php-7.0.9/etc/php/opcache.ini, /usr/local/php-7.0.9/etc/php/phpredis.ini, /usr/local/php-7.0.9/etc/php/pinba.ini
PHP API | 20151012
PHP Extension | 20151012
Zend Extension | 320151012
Zend Extension Build | API320151012,NTS
PHP Extension Build | API20151012,NTS
Debug Build | no
Thread Safety | disabled
Zend Signal Handling | disabled
Zend Memory Manager | enabled
Zend Multibyte Support | provided by mbstring
IPv6 Support | disabled
DTrace Support | disabled
Registered PHP Streams | https, ftps, compress.zlib, compress.bzip2, php, file, glob, data, http, ftp, phar, zip
Registered Stream Socket Transports | tcp, udp, unix, udg, ssl, sslv3, sslv2, tls, tlsv1.0
Registered Stream Filters | zlib.*, bzip2.*, convert.iconv.*, mcrypt.*, mdecrypt.*, string.rot13, string.toupper, string.tolower, string.strip_tags, convert.*, consumed, dechunk
Blitz support | enabled
-- | --
Version | 0.10.3.1
-- | -- | --
blitz.auto_escape | 0 | 0
blitz.check_recursion | 1 | 1
blitz.comment_close | */ | */
blitz.comment_open | /* | /*
blitz.enable_alternative_tags | 0 | 1
blitz.enable_callbacks | 1 | 1
blitz.enable_comments | 0 | 0
blitz.enable_include | 1 | 1
blitz.enable_php_callbacks | 1 | 1
blitz.lower_case_method_names | 1 | 1
blitz.path | no value | no value
blitz.php_callbacks_first | 1 | 1
blitz.remove_spaces_around_context_tags | 1 | 1
blitz.scope_lookup_limit | 0 | 0
blitz.tag_close | }} | }}
blitz.tag_close_alt | --> | -->
blitz.tag_open | {{ | {{
blitz.tag_open_alt | <!-- | <!--
blitz.throw_exceptions | 0 | 0
blitz.var_prefix | $ | $
blitz.warn_context_duplicates | 0 | 0
P. S.
My apologies for "excellent" English
Interesting. Not sure you compare comparable things though, but this can be a good exercise to debug at lower levels to see what is allocated exactly and when.
Which Timer class do you use?
Maybe you are right, we would not have paid attention if we did not face the errors of the "Fatal error: Allowed memory size of N-th bytes exhausted".
The first thing we suspected was our incorrect code, but after the measurements we came to the conclusion that the source of the error lies in the method call parse().
The process, working with the text of 25 Mb in length (well, we have a specific text), goes beyond of the 128 MB limit.
Test-specific Timer class implementation:
class Timer
{
private static $timers = array();
public static function start($namepsace, $operation)
{
$timer['memory_peak_start'] = memory_get_peak_usage($real = true);
$timer['memory_start'] = memory_get_usage($real = true);
$timer['nested_level'] = count(static::$timers);
$timer['microtime_start'] = microtime($float = true);
$timer['namespace'] = $namepsace;
$timer['operation'] = $operation;
static::$timers[] = $timer;
}
public static function stop()
{
if ($timer = end(static::$timers)) {
$key = key(static::$timers);
$timer['memory_peak_stop'] = memory_get_peak_usage($real = true);
$timer['memory_stop'] = memory_get_usage($real = true);
$timer['microtime_stop'] = microtime($float = true);
static::$timers[$key] = $timer;
}
}
public static function dump()
{
$timers = static::$timers;
foreach ($timers as &$timer) {
$timer['microtime_diff'] = $timer['microtime_stop'] - $timer['microtime_start'];
$timer['memory_peak_diff'] = $timer['memory_peak_stop'] - $timer['memory_peak_start'];
$timer['memory_diff'] = $timer['memory_stop'] - $timer['memory_start'];
}
return $timers;
}
}Real implementaion of Timer class (requires Pinba extension):
class Timer
{
private static $extended = true;
private static $timers = array();
private static function activated()
{
return true;
}
public static function start($group, $operation, $server = 'default', array $data = array())
{
if (!self::activated()) {
return;
}
if (self::$extended) {
$data['memory_peak_start'] = memory_get_peak_usage();
$data['memory_start'] = memory_get_usage();
$data['nested_level'] = count(static::$timers);
}
static::$timers[] = pinba_timer_start(array(
'group' => $group,
'operation' => $operation,
'server' => $server
), self::$extended ? $data : array());
}
public static function stop(array $data = array())
{
if (!self::activated()) {
return;
}
if (($timer = end(static::$timers))) {
pinba_timer_stop($timer);
unset(static::$timers[key(static::$timers)]);
if (self::$extended) {
$data['memory_peak_stop'] = memory_get_peak_usage();
$data['memory_stop'] = memory_get_usage();
pinba_timer_data_merge($timer, $data);
}
}
}
public static function dump()
{
$output = array();
if (self::activated()) {
$output = pinba_get_info();
}
return $output;
}
// ...
}We changed the Blitz extension settings, but this action had no effect
ini_set('blitz.check_recursion', '0');
ini_set('blitz.enable_php_callbacks', '0');
ini_set('blitz.enable_callbacks', '0');
ini_set('blitz.enable_include', '0');
ini_set('blitz.remove_spaces_around_context_tags', '0');At the moment we are confused until we know if the effect of memory consumption growth actually takes place or our code is so bad. So we decided to ask you for advice.
Thanks, I will try to repeat, play with sources, probably track allocations and come back. This should not happen - just one tag with long value, I dont understand this from scratch.
@RogulinSV Sergey, first of all thanks a lot for this finding!
Not sure this can be fixed quickly and total memory peak usage will be reduced to str_replace memory usage, however there is definitely a space to optimise how blitz works with memory.
Writing the research results below as probably there are several places to fix.
In the example above we have extremely long value of a parameter - string of 20MB, and there are several stages when copying occures: iterations merge, execution of a template, and returning a result.
== debugging inside the blitz_parse method (blitz.c)
MEMSTAT#0: peak_used = 46516848, peak_real = 48242688 (blitz_parse just called)
MEMSTAT#1: peak_used = 69590400, peak_real = 71315456 (iterations merged)
MEMSTAT#2: peak_used = 113634760, peak_real = 115359744 (template executed)
MEMSTAT#3: peak_used = 136707504, peak_real = 138432512 (return value copied)
MEMSTAT#4: peak_used = 136707808, peak_real = 138432512 (result freed)
== result of the test script (moved replace before parse)
debug::fetch
Time: 0.00949311256409
Memory: 2097152 -> 25169920 (23072768)
Max Memory: 25169920
debug::replace
Time: 0.0131888389587
Memory: 25169920 -> 48242688 (23072768)
Max Memory: 48242688
debug::parse
Time: 0.0400040149689
Memory: 48242688 -> 71315456 (23072768)
Max Memory: 138432512
== stupid math
php -r 'echo 71315456 - 48242688, "\n";' 23072768 php -r 'echo 115359744 - 71315456, "\n";' 44044288 php -r 'echo 138432512 - 115359744, "\n";' 23072768 php -r 'echo 22*1024*1024, "\n";' 23068672
We would be very grateful to you for the optimization.
We have a big project (as it seems to us), based on "three pillars of the universe": a blitz template engine, a caching mechanism and dirty hacks.
@tony2001 could you push your patches to the PHP7 branch please?
@RogulinSV JFYI #54
Alexey, Antony, hello!
Sorry for the delay. We are only now started testing the latest release. It will take some time, but now, according to the tests, the results are more than impressive.
closing?
Yes, thank you for updating