debugParser: время парсинга некэшируемых сниппетов
Вопрос касается времени парсинга (без выполнения) некэшируемых снипптов, замеряемое через debugParser.
3. Имеется некэшируемый сниппет snp01:
— время выполнения кода сниппета: 0.01-0.02 сек
— время парсинга сниппета, показанное debugParser: 0.3 сек
— объём сниппета: 1000 строк кода = 55 Кб
— время считывания/подключения include-файла сниппета (core/cache/includes/elements/modsnippet/xxx.include.cache.php): 0.003-0.004 сек
— разница между временем парсинга и временем выполнения кода: 0.28 сек
2. Имеется некэшируемый сниппет snp02:
— время выполнения кода сниппета: 0.018 сек
— время парсинга сниппета, показанное debugParser: 0.04-0.05 сек
— объём сниппета: 145 строк кода = 6,5 Кб
— время считывания/подключения include-файла сниппета (core/cache/includes/elements/modsnippet/xxx.include.cache.php): 0.0004 сек
— разница между временем парсинга и временем выполнения кода: 0.03 сек
Получаем такую тенденцию: чем большер размер сниппета, тем дольше он парсится. Какие же такие масштабные операции над сниппетами (зависящие от текстового объёма сниппета) выполняет modx ?
Ведь сниппет — не чанк и никакие теги там парсить не нужно.
На одном лишь сниппете snp01 потеря времени составляет 0.28 сек, при этом код сниппета выполняется 0.01-0.02 сек, а include-файл сниппета считывается с диска 0.004 сек.
3. Имеется некэшируемый сниппет snp01:
— время выполнения кода сниппета: 0.01-0.02 сек
— время парсинга сниппета, показанное debugParser: 0.3 сек
— объём сниппета: 1000 строк кода = 55 Кб
— время считывания/подключения include-файла сниппета (core/cache/includes/elements/modsnippet/xxx.include.cache.php): 0.003-0.004 сек
— разница между временем парсинга и временем выполнения кода: 0.28 сек
2. Имеется некэшируемый сниппет snp02:
— время выполнения кода сниппета: 0.018 сек
— время парсинга сниппета, показанное debugParser: 0.04-0.05 сек
— объём сниппета: 145 строк кода = 6,5 Кб
— время считывания/подключения include-файла сниппета (core/cache/includes/elements/modsnippet/xxx.include.cache.php): 0.0004 сек
— разница между временем парсинга и временем выполнения кода: 0.03 сек
Получаем такую тенденцию: чем большер размер сниппета, тем дольше он парсится. Какие же такие масштабные операции над сниппетами (зависящие от текстового объёма сниппета) выполняет modx ?
Ведь сниппет — не чанк и никакие теги там парсить не нужно.
На одном лишь сниппете snp01 потеря времени составляет 0.28 сек, при этом код сниппета выполняется 0.01-0.02 сек, а include-файл сниппета считывается с диска 0.004 сек.
Комментарии: 29
В сниппет snp01 поместил минимальный код:
Как такое может быть? Напрашивается вывод, что modx очень тщательно парсит код сниппета. Но чего там парсить? Ведь в сниппетах нет modx-тегов — только php-код и всё.
Единственной разницей во времени парсинга должна быть разница между чтением с диска маленького файла и большого — а это тысячные и сотые доли секунды соответственно. Де факто получаем разницу в 0.3 сек.
return '000';
В итоге время парсинга сниппета уменьшилось с 0.3 сек до 0.002 секКак такое может быть? Напрашивается вывод, что modx очень тщательно парсит код сниппета. Но чего там парсить? Ведь в сниппетах нет modx-тегов — только php-код и всё.
Единственной разницей во времени парсинга должна быть разница между чтением с диска маленького файла и большого — а это тысячные и сотые доли секунды соответственно. Де факто получаем разницу в 0.3 сек.
Можно было бы предположить, что причина в объёме html-кода, который возвращает этот сниппет (объём немалый) — этот возвращаемый html-код modx может долго парсить.
Но если в сниппете snp01 весь код оставить, но вместо
Следовательно, 0.3 сек уходит НЕ на парсинг возвращаемого сниппептом html-кода.
P.S. Т.е. время парсинга некэшируемого сниппета приблизительно пропорционально текстовому объёму кода этого сниппета и не зависит от возвращаемого сниппетом значения. И коэффициент пропорциональности имеет приличную величину.
Но если в сниппете snp01 весь код оставить, но вместо
return $output; // возвращается большой объём html-кода
поставитьreturn '000';
то время парсинга сниппета нисколько не уменьшается — также 0.3 секСледовательно, 0.3 сек уходит НЕ на парсинг возвращаемого сниппептом html-кода.
P.S. Т.е. время парсинга некэшируемого сниппета приблизительно пропорционально текстовому объёму кода этого сниппета и не зависит от возвращаемого сниппетом значения. И коэффициент пропорциональности имеет приличную величину.
Как измеряется время выполнения сниппета?
<?php
$time0 = microtime(true);
... // код сниппета: в $output набирается html-код
print_r(number_format(microtime(true) - $time0, 4).' сек');
return $output;
Наберите в сниппете любой левый код на 3000 строк (который выполняется быстро) и запустите debugParser. Получите приличное время для этого сниппета.
Сделал сниппет из более 3500 строк $res = $modx->getObject('modResource', rand(200));
Результат парсера — 0.0310622
Время через микротайм — 0.0075538158416748
Результат парсера — 0.0310622
Время через микротайм — 0.0075538158416748
Ну вот. У Вас уже чисто на парсинг уходит 0.02 сек.
Учитывая, что у меня сервер слабый (работает в 20-40 раз медленнее, чем тот сервер, на котором работает Василий), можете умножить Ваши цифры на 10 и получите тот же масштаб цифр (0.3 сек и 0.075 сек соответственно)
А теперь уберите все 3500 строк и посмотрите, сколько будет парситься почти пустой сниппет.
Учитывая, что у меня сервер слабый (работает в 20-40 раз медленнее, чем тот сервер, на котором работает Василий), можете умножить Ваши цифры на 10 и получите тот же масштаб цифр (0.3 сек и 0.075 сек соответственно)
А теперь уберите все 3500 строк и посмотрите, сколько будет парситься почти пустой сниппет.
Пустой сниппет — 0.005213
Сниппет с 3500 строками кода парсится (без выполнения): 0.0311 — 0.0076 = 0.0235 сек
Сниппет без кода парсится: 0.0052 сек.
А теперь вопрос: куда подевались 0.02 сек?
Чтение include-файла сниппета с 3500 строками кода занимает тысячные (у Вас — десятитысячные) доли секунды.
Т.е. в случае с 3500 строками кода чисто парсинг (без выполнения) длится на 0.02 сек дольше, чем парсинг пустого (или почти пустого) сниппета.
Сниппет без кода парсится: 0.0052 сек.
А теперь вопрос: куда подевались 0.02 сек?
Чтение include-файла сниппета с 3500 строками кода занимает тысячные (у Вас — десятитысячные) доли секунды.
Т.е. в случае с 3500 строками кода чисто парсинг (без выполнения) длится на 0.02 сек дольше, чем парсинг пустого (или почти пустого) сниппета.
А чтобы разница была ощутимее, сделайте не 3500 строк кода, а 10000 строк кода.
И сравните время парсинга сниппета с этими 10000 строками кода и без них.
А код возьмите полегче, чтобы быстро выполнялся, например:
И сравните время парсинга сниппета с этими 10000 строками кода и без них.
А код возьмите полегче, чтобы быстро выполнялся, например:
$var = array_key_exists('ttt', $modx->placeholders) || array_key_exists('yyy', $modx->placeholders);
если в коде оставить несуществующий плейсходер то парсер будет елозить до последнего…
Да, действительно. У меня в одном чанке остался вызов [[+landing]], тогда как simpleSearch я уже давно как снёс (руки всё никак не доходили):
community.modx-cms.ru/blog/questions/199388.html#comment77053
Но на скорость загрузки страницы это никак не повлияло (разве что на 0.05 сек, не более). И тем более, никак не повлияло на сабжевую проблему.
community.modx-cms.ru/blog/questions/199388.html#comment77053
Но на скорость загрузки страницы это никак не повлияло (разве что на 0.05 сек, не более). И тем более, никак не повлияло на сабжевую проблему.
Получается так:
— время выполнения кода сниппета: 0.01-0.02 сек
— время парсинга сниппета, показанное debugParser: 0.07-0.30 сек
— разница между временем парсинга и временем выполнения кода: 0.05-0.28 сек
Т.е. сегодня в течение 3-4 часов время парсинга менялось в довольно широком диапазоне 0.05-0.30 сек, при этом время выполнения сниппета не менялось и всё время составляло 0.01-0.02 сек.
Но даже если взять минимальное время парсинга (0.04 сек), то всё равно чисто на парсинг (без выполнения) уходит слишком много времени — 0.05 сек. При этом чтение include-файла сниппета core/cache/includes/elements/modsnippet/xxx.include.cache.php выполняется за тысячные доли секунды.
— время выполнения кода сниппета: 0.01-0.02 сек
— время парсинга сниппета, показанное debugParser: 0.07-0.30 сек
— разница между временем парсинга и временем выполнения кода: 0.05-0.28 сек
Т.е. сегодня в течение 3-4 часов время парсинга менялось в довольно широком диапазоне 0.05-0.30 сек, при этом время выполнения сниппета не менялось и всё время составляло 0.01-0.02 сек.
Но даже если взять минимальное время парсинга (0.04 сек), то всё равно чисто на парсинг (без выполнения) уходит слишком много времени — 0.05 сек. При этом чтение include-файла сниппета core/cache/includes/elements/modsnippet/xxx.include.cache.php выполняется за тысячные доли секунды.
Вот сейчас снова сниппет парсится 0.3-0.4 сек. при этом код сниппета выполняется стабильно 0.01-0.02 сек.
Явно modx что-там делает усиленно. Причём временами эти его действия занимают много времени (0.3 сек), временами — мало (0.03 сек).
Причём ошибок замеров здесь нет, потому что общее время генерации скрипта, выводимое через тег [^t^], также увеличилось на 0.3 сек. Т.е. время парсинга сниппета (без выполнения кода) на самом деле тормозит.
Попробую поковыряться в исходниках…
Явно modx что-там делает усиленно. Причём временами эти его действия занимают много времени (0.3 сек), временами — мало (0.03 сек).
Причём ошибок замеров здесь нет, потому что общее время генерации скрипта, выводимое через тег [^t^], также увеличилось на 0.3 сек. Т.е. время парсинга сниппета (без выполнения кода) на самом деле тормозит.
Попробую поковыряться в исходниках…
Вот мой тест:
В файле /core/model/modx/modparser.class.php внутрь метода processTag (строка 414) ставим 3 заглушки:
Далее в файле /core/model/modx/modelement.class.php внутрь метода process (строка 263) ставим ещё 2 заглушки:
Загружаем страницу и получаем цифры:
[before process] 0.0023
[start process] 0.0024
[end process] 0.0032
[after process] 0.0436
Т.е наблюдается большой скачок времени (0.04 сек) между лапками [end process] и [after process]. Этот промежуток времени соответствует возврату из метода modElement::process() обратно в метод modParser::processTag(), откуда он был вызван.
Временной провал локализован и составляет 0.04. Осталось это чудо объяснить.
В файле /core/model/modx/modparser.class.php внутрь метода processTag (строка 414) ставим 3 заглушки:
public function processTag($tag, $processUncacheable = true) {
/* STUB: start time */ if($tag[0] == '[[!snp01]]') { $GLOBALS['time0'] = microtime(true); }
...
if ($elementOutput === null) {
switch ($token) {
...
default:
$tagName= substr($tagName, $tokenOffset);
if ($element= $this->getElement('modSnippet', $tagName)) {
$element->set('name', $tagName);
$element->setTag($outerTag);
$element->setCacheable($cacheable);
/* STUB */ if($tag[0] == '[[!snp01]]') { print_r('[before process] '.number_format(microtime(true) - $GLOBALS['time0'], 4), false); }
$elementOutput= $element->process($tagPropString);
/* STUB */ if($tag[0] == '[[!snp01]]') { print_r('[after process] '.number_format(microtime(true) - $GLOBALS['time0'], 4), false); }
}
}
}
...
}
Далее в файле /core/model/modx/modelement.class.php внутрь метода process (строка 263) ставим ещё 2 заглушки:
public function process($properties= null, $content= null) {
/* STUB */ if($this->_tag == '[[!snp01]]') { print_r('[start process] '.number_format(microtime(true) - $GLOBALS['time0'], 4), false); }
$this->xpdo->getParser();
$this->xpdo->parser->setProcessingElement(true);
$this->getProperties($properties);
$this->getTag();
if ($this->xpdo->getDebug() === true) $this->xpdo->log(xPDO::LOG_LEVEL_DEBUG, "Processing Element: " . $this->get('name') . ($this->_tag ? "\nTag: {$this->_tag}" : "\n") . "\nProperties: " . print_r($this->_properties, true));
if ($this->isCacheable() && isset ($this->xpdo->elementCache[$this->_tag])) {
$this->_output = $this->xpdo->elementCache[$this->_tag];
$this->_processed = true;
} else {
$this->filterInput();
$this->getContent(is_string($content) ? array('content' => $content) : array());
}
/* STUB */ if($this->_tag == '[[!snp01]]') { print_r('[end process] '.number_format(microtime(true) - $GLOBALS['time0'], 4), false); }
return $this->_result; // NOTE: [$this->_result] return true
}
Загружаем страницу и получаем цифры:
[before process] 0.0023
[start process] 0.0024
[end process] 0.0032
[after process] 0.0436
Т.е наблюдается большой скачок времени (0.04 сек) между лапками [end process] и [after process]. Этот промежуток времени соответствует возврату из метода modElement::process() обратно в метод modParser::processTag(), откуда он был вызван.
Временной провал локализован и составляет 0.04. Осталось это чудо объяснить.
Тьфу. Нужно было не modElement::process() смотреть, а modScript::process()
Проверил. Всё-таки эти 0.3-0.4 секунды уходят на парсинг html-кода, возвращаемого сниппетом (modParser::processElementTags()). А в этом html-коде много тегов modx (150 штук, в основном, cсылки вида [[~...]]):
Иногда на парсинг этих 150 тегов уходит 0.10-0.15 сек, иногда 0.05 сек, временами 0.3-0.4 сек.
public function processElementTags($parentTag, & $content, $processUncacheable= false, $removeUnprocessed= false, $prefix= "[[", $suffix= "]]", $tokens= array (), $depth= 0) {
$_processingTag = $this->_processingTag;
$_processingUncacheable = $this->_processingUncacheable;
$_removingUnprocessed = $this->_removingUnprocessed;
$this->_processingTag = true;
$this->_processingUncacheable = (boolean) $processUncacheable;
$this->_removingUnprocessed = (boolean) $removeUnprocessed;
$depth = $depth > 0 ? $depth - 1 : 0;
$processed= 0;
$tags= array ();
/* invoke OnParseDocument event */
$this->modx->documentOutput = $content;
$this->modx->invokeEvent('OnParseDocument', array('content' => &$content));
$content = $this->modx->documentOutput;
unset($this->modx->documentOutput);
if ($collected= $this->collectElementTags($content, $tags, $prefix, $suffix, $tokens)) {
$tagMap= array ();
foreach ($tags as $tag) {
$token= substr($tag[1], 0, 1);
if (!$processUncacheable && $token === '!') {
if ($removeUnprocessed) {
$tagMap[$tag[0]]= '';
}
}
elseif (!empty ($tokens) && !in_array($token, $tokens)) {
$collected--;
continue;
}
if ($tag[0] === $parentTag) {
$tagMap[$tag[0]]= '';
$processed++;
continue;
}
$tagOutput= $this->processTag($tag, $processUncacheable);
if (($tagOutput === null || $tagOutput === false) && $removeUnprocessed) {
$tagMap[$tag[0]]= '';
$processed++;
}
elseif ($tagOutput !== null && $tagOutput !== false) {
$tagMap[$tag[0]]= $tagOutput;
if ($tag[0] !== $tagOutput) $processed++;
}
}
$this->mergeTagOutput($tagMap, $content);
if ($depth > 0) {
$processed+= $this->processElementTags($parentTag, $content, $processUncacheable, $removeUnprocessed, $prefix, $suffix, $tokens, $depth);
}
}
$this->_removingUnprocessed = $_removingUnprocessed;
$this->_processingUncacheable = $_processingUncacheable;
$this->_processingTag = $_processingTag;
return $processed;
}
Иногда на парсинг этих 150 тегов уходит 0.10-0.15 сек, иногда 0.05 сек, временами 0.3-0.4 сек.
…
С помощью плагина на OnParseDocument можно было бы маскировать modx-теги внутри чанков и внутри возвращаемых сниппетами html-фрагментов (чтобы эти теги не обрабатывались сразу), а перед конечным прогоном парсера их размаскировать, чтобы все теги были обработаны за раз.
Но при создании плагина (даже пустого) время генерации страницы увеличивается на полсекунды из-за большого числа вызовов этого плагина. Т.е. вариант с OnParseDocument отпадает…
Но при создании плагина (даже пустого) время генерации страницы увеличивается на полсекунды из-за большого числа вызовов этого плагина. Т.е. вариант с OnParseDocument отпадает…
думаю фигня получится… и ты где нибудь что то потеряешь…
Если что-то и «потеряется», то оно «вылезет» в конечном html.
Да оно конечно потеряется и оно конечно вылезет, только как думаешь вылезет? Я плейсходер — я потерялся? Будет просто пусто… И даже если ты определишь что потерялось что дальше с этим делать?
Я плейсходер — я потерялся? Будет просто пусто…
Нет. Будет замаскированный плейсхолдер. Или Вы под «маскировкой» поняли удаление из html? Если удалять, то потом не вычислишь позицию вставки в html.И даже если ты определишь что потерялось что дальше с этим делать?
Исправлять логические ошибки.
Нужно свой парсер написать. То что modx сейчас парсит 0.3 сек, с помощью регулярок можно распарсить за 0.01 сек.
Плюс сразу парсить элементы по мере их «поступления» не нужно. Лучше их распарсить в самом конце после полного разворачивания элементов за один раз. так будет гораздо быстрее.
Плюс сразу парсить элементы по мере их «поступления» не нужно. Лучше их распарсить в самом конце после полного разворачивания элементов за один раз. так будет гораздо быстрее.
Ты пробовал включать парсер pdoTools? И сравнить со стандартным?
По возможности я стараюсь обходиться стандартным функционалом modx. Только в этом случае при обновлении версии modx гарантированно не будет никаких серьёзных проблем.
А обоснование выставленному минусу будет? Или это не принято?
Я сторонник конструктива — а Вы?
Я сторонник конструктива — а Вы?
Я тут не причем. Хотя логики между «Нужно свой парсер написать» и «По возможности я стараюсь обходиться стандартным функционалом modx.» не вижу).
Под «обходиться стандартным функционалом modx» я имею ввиду «по возможности не использовать third-party-код». Т.е. по возможности стандартный функционал modx + собственный код (который находится под твоим собственным контролем).
Сейчас из всего стороннего я использую только pdoTools::getChunk() и minifyX. Да и то — в настройках их можно отключить — и сайт по-прежнему будет работать на базовом функционале без изменения кода (чуть медленнее, но будет работать). Т.е. если что-то перестанет работать, его отключаю и спокойно отлаживаю). Именно такой логики работы изначально придерживаюсь при использовании небазовых компонентов.
Всё остальное (включая pdoResources, пагинация и т.д. и т.п.) реализовано на собственных функциях, классах, обвязках.
P.S. А теперь ждём конструктива от автора минуса…
Всё остальное (включая pdoResources, пагинация и т.д. и т.п.) реализовано на собственных функциях, классах, обвязках.
P.S. А теперь ждём конструктива от автора минуса…
Авторизуйтесь или зарегистрируйтесь, чтобы оставлять комментарии.