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 сек.
Cyrax_02
06 октября 2014, 10:41
modx.pro
2 012
0

Комментарии: 29

Cyrax_02
06 октября 2014, 15:26
0
В сниппет snp01 поместил минимальный код:
return '000';
В итоге время парсинга сниппета уменьшилось с 0.3 сек до 0.002 сек

Как такое может быть? Напрашивается вывод, что modx очень тщательно парсит код сниппета. Но чего там парсить? Ведь в сниппетах нет modx-тегов — только php-код и всё.
Единственной разницей во времени парсинга должна быть разница между чтением с диска маленького файла и большого — а это тысячные и сотые доли секунды соответственно. Де факто получаем разницу в 0.3 сек.
    Cyrax_02
    06 октября 2014, 15:49
    0
    Можно было бы предположить, что причина в объёме html-кода, который возвращает этот сниппет (объём немалый) — этот возвращаемый html-код modx может долго парсить.

    Но если в сниппете snp01 весь код оставить, но вместо
    return $output;  // возвращается большой объём html-кода
    поставить
    return '000';
    то время парсинга сниппета нисколько не уменьшается — также 0.3 сек

    Следовательно, 0.3 сек уходит НЕ на парсинг возвращаемого сниппептом html-кода.

    P.S. Т.е. время парсинга некэшируемого сниппета приблизительно пропорционально текстовому объёму кода этого сниппета и не зависит от возвращаемого сниппетом значения. И коэффициент пропорциональности имеет приличную величину.
      Виталий Киреев
      06 октября 2014, 15:52
      0
      Как измеряется время выполнения сниппета?
        Cyrax_02
        06 октября 2014, 16:45
        0
        <?php
        $time0 = microtime(true);
        ... // код сниппета: в $output набирается html-код
        print_r(number_format(microtime(true) - $time0, 4).' сек');
        return $output;

        Наберите в сниппете любой левый код на 3000 строк (который выполняется быстро) и запустите debugParser. Получите приличное время для этого сниппета.
          Виталий Киреев
          06 октября 2014, 16:50
          0
          Сделал сниппет из более 3500 строк $res = $modx->getObject('modResource', rand(200));
          Результат парсера — 0.0310622
          Время через микротайм — 0.0075538158416748
            Cyrax_02
            06 октября 2014, 17:21
            0
            Ну вот. У Вас уже чисто на парсинг уходит 0.02 сек.
            Учитывая, что у меня сервер слабый (работает в 20-40 раз медленнее, чем тот сервер, на котором работает Василий), можете умножить Ваши цифры на 10 и получите тот же масштаб цифр (0.3 сек и 0.075 сек соответственно)

            А теперь уберите все 3500 строк и посмотрите, сколько будет парситься почти пустой сниппет.
              Виталий Киреев
              06 октября 2014, 17:24
              0
              Пустой сниппет — 0.005213
                Cyrax_02
                06 октября 2014, 17:30
                0
                Сниппет с 3500 строками кода парсится (без выполнения): 0.0311 — 0.0076 = 0.0235 сек
                Сниппет без кода парсится: 0.0052 сек.

                А теперь вопрос: куда подевались 0.02 сек?
                Чтение include-файла сниппета с 3500 строками кода занимает тысячные (у Вас — десятитысячные) доли секунды.

                Т.е. в случае с 3500 строками кода чисто парсинг (без выполнения) длится на 0.02 сек дольше, чем парсинг пустого (или почти пустого) сниппета.
                  Cyrax_02
                  06 октября 2014, 17:36
                  0
                  А чтобы разница была ощутимее, сделайте не 3500 строк кода, а 10000 строк кода.
                  И сравните время парсинга сниппета с этими 10000 строками кода и без них.

                  А код возьмите полегче, чтобы быстро выполнялся, например:
                  $var = array_key_exists('ttt', $modx->placeholders) || array_key_exists('yyy', $modx->placeholders);
          Володя
          06 октября 2014, 16:41
          +1
          если в коде оставить несуществующий плейсходер то парсер будет елозить до последнего…
            Cyrax_02
            06 октября 2014, 17:16
            0
            Да, действительно. У меня в одном чанке остался вызов [[+landing]], тогда как simpleSearch я уже давно как снёс (руки всё никак не доходили):
            community.modx-cms.ru/blog/questions/199388.html#comment77053

            Но на скорость загрузки страницы это никак не повлияло (разве что на 0.05 сек, не более). И тем более, никак не повлияло на сабжевую проблему.
            Cyrax_02
            06 октября 2014, 19:13
            0
            Получается так:
            — время выполнения кода сниппета: 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 выполняется за тысячные доли секунды.
              Cyrax_02
              06 октября 2014, 19:32
              0
              Вот сейчас снова сниппет парсится 0.3-0.4 сек. при этом код сниппета выполняется стабильно 0.01-0.02 сек.
              Явно modx что-там делает усиленно. Причём временами эти его действия занимают много времени (0.3 сек), временами — мало (0.03 сек).
              Причём ошибок замеров здесь нет, потому что общее время генерации скрипта, выводимое через тег [^t^], также увеличилось на 0.3 сек. Т.е. время парсинга сниппета (без выполнения кода) на самом деле тормозит.

              Попробую поковыряться в исходниках…
                Cyrax_02
                06 октября 2014, 21:55
                0
                Вот мой тест:
                В файле /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. Осталось это чудо объяснить.
                  Cyrax_02
                  06 октября 2014, 22:32
                  0
                  Тьфу. Нужно было не modElement::process() смотреть, а modScript::process()
                  Cyrax_02
                  07 октября 2014, 13:28
                  0
                  Проверил. Всё-таки эти 0.3-0.4 секунды уходят на парсинг html-кода, возвращаемого сниппетом (modParser::processElementTags()). А в этом html-коде много тегов modx (150 штук, в основном, cсылки вида [[~...]]):

                  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 сек.
                    Cyrax_02
                    07 октября 2014, 15:19
                    0
                    Cyrax_02
                    07 октября 2014, 15:19
                    0
                    С помощью плагина на OnParseDocument можно было бы маскировать modx-теги внутри чанков и внутри возвращаемых сниппетами html-фрагментов (чтобы эти теги не обрабатывались сразу), а перед конечным прогоном парсера их размаскировать, чтобы все теги были обработаны за раз.
                    Но при создании плагина (даже пустого) время генерации страницы увеличивается на полсекунды из-за большого числа вызовов этого плагина. Т.е. вариант с OnParseDocument отпадает…
                      Володя
                      07 октября 2014, 16:01
                      +1
                      думаю фигня получится… и ты где нибудь что то потеряешь…
                        Cyrax_02
                        08 октября 2014, 02:31
                        0
                        Если что-то и «потеряется», то оно «вылезет» в конечном html.
                          Володя
                          08 октября 2014, 07:47
                          0
                          Да оно конечно потеряется и оно конечно вылезет, только как думаешь вылезет? Я плейсходер — я потерялся? Будет просто пусто… И даже если ты определишь что потерялось что дальше с этим делать?
                            Cyrax_02
                            08 октября 2014, 13:32
                            0
                            Я плейсходер — я потерялся? Будет просто пусто…
                            Нет. Будет замаскированный плейсхолдер. Или Вы под «маскировкой» поняли удаление из html? Если удалять, то потом не вычислишь позицию вставки в html.

                            И даже если ты определишь что потерялось что дальше с этим делать?
                            Исправлять логические ошибки.
                      Cyrax_02
                      07 октября 2014, 15:23
                      0
                      Нужно свой парсер написать. То что modx сейчас парсит 0.3 сек, с помощью регулярок можно распарсить за 0.01 сек.
                      Плюс сразу парсить элементы по мере их «поступления» не нужно. Лучше их распарсить в самом конце после полного разворачивания элементов за один раз. так будет гораздо быстрее.
                        Виталий Киреев
                        08 октября 2014, 09:57
                        0
                        Ты пробовал включать парсер pdoTools? И сравнить со стандартным?
                          Cyrax_02
                          08 октября 2014, 13:34
                          -1
                          По возможности я стараюсь обходиться стандартным функционалом modx. Только в этом случае при обновлении версии modx гарантированно не будет никаких серьёзных проблем.
                            Cyrax_02
                            08 октября 2014, 16:54
                            0
                            А обоснование выставленному минусу будет? Или это не принято?
                            Я сторонник конструктива — а Вы?
                              Виталий Киреев
                              08 октября 2014, 16:56
                              +1
                              Я тут не причем. Хотя логики между «Нужно свой парсер написать» и «По возможности я стараюсь обходиться стандартным функционалом modx.» не вижу).
                                Cyrax_02
                                08 октября 2014, 17:03
                                0
                                Под «обходиться стандартным функционалом modx» я имею ввиду «по возможности не использовать third-party-код». Т.е. по возможности стандартный функционал modx + собственный код (который находится под твоим собственным контролем).
                                  Cyrax_02
                                  08 октября 2014, 17:12
                                  0
                                  Сейчас из всего стороннего я использую только pdoTools::getChunk() и minifyX. Да и то — в настройках их можно отключить — и сайт по-прежнему будет работать на базовом функционале без изменения кода (чуть медленнее, но будет работать). Т.е. если что-то перестанет работать, его отключаю и спокойно отлаживаю). Именно такой логики работы изначально придерживаюсь при использовании небазовых компонентов.
                                  Всё остальное (включая pdoResources, пагинация и т.д. и т.п.) реализовано на собственных функциях, классах, обвязках.

                                  P.S. А теперь ждём конструктива от автора минуса…
                            Авторизуйтесь или зарегистрируйтесь, чтобы оставлять комментарии.
                            29