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
Авторизуйтесь или зарегистрируйтесь, чтобы оставлять комментарии.
В итоге время парсинга сниппета уменьшилось с 0.3 сек до 0.002 сек
Как такое может быть? Напрашивается вывод, что modx очень тщательно парсит код сниппета. Но чего там парсить? Ведь в сниппетах нет modx-тегов — только php-код и всё.
Единственной разницей во времени парсинга должна быть разница между чтением с диска маленького файла и большого — а это тысячные и сотые доли секунды соответственно. Де факто получаем разницу в 0.3 сек.
Но если в сниппете snp01 весь код оставить, но вместо
поставить
то время парсинга сниппета нисколько не уменьшается — также 0.3 сек
Следовательно, 0.3 сек уходит НЕ на парсинг возвращаемого сниппептом html-кода.
P.S. Т.е. время парсинга некэшируемого сниппета приблизительно пропорционально текстовому объёму кода этого сниппета и не зависит от возвращаемого сниппетом значения. И коэффициент пропорциональности имеет приличную величину.
Наберите в сниппете любой левый код на 3000 строк (который выполняется быстро) и запустите debugParser. Получите приличное время для этого сниппета.
Результат парсера — 0.0310622
Время через микротайм — 0.0075538158416748
Учитывая, что у меня сервер слабый (работает в 20-40 раз медленнее, чем тот сервер, на котором работает Василий), можете умножить Ваши цифры на 10 и получите тот же масштаб цифр (0.3 сек и 0.075 сек соответственно)
А теперь уберите все 3500 строк и посмотрите, сколько будет парситься почти пустой сниппет.
Сниппет без кода парсится: 0.0052 сек.
А теперь вопрос: куда подевались 0.02 сек?
Чтение include-файла сниппета с 3500 строками кода занимает тысячные (у Вас — десятитысячные) доли секунды.
Т.е. в случае с 3500 строками кода чисто парсинг (без выполнения) длится на 0.02 сек дольше, чем парсинг пустого (или почти пустого) сниппета.
И сравните время парсинга сниппета с этими 10000 строками кода и без них.
А код возьмите полегче, чтобы быстро выполнялся, например:
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 выполняется за тысячные доли секунды.
Явно 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. Осталось это чудо объяснить.
Иногда на парсинг этих 150 тегов уходит 0.10-0.15 сек, иногда 0.05 сек, временами 0.3-0.4 сек.
Но при создании плагина (даже пустого) время генерации страницы увеличивается на полсекунды из-за большого числа вызовов этого плагина. Т.е. вариант с OnParseDocument отпадает…
Исправлять логические ошибки.
Плюс сразу парсить элементы по мере их «поступления» не нужно. Лучше их распарсить в самом конце после полного разворачивания элементов за один раз. так будет гораздо быстрее.
Я сторонник конструктива — а Вы?
Всё остальное (включая pdoResources, пагинация и т.д. и т.п.) реализовано на собственных функциях, классах, обвязках.
P.S. А теперь ждём конструктива от автора минуса…