Статистика количества запросов и времени на исполнение в MODX Revolution

Получил в личку очень интересный вопрос. Цитирую:
 
Не могли бы вы помочь мне с Рево — никак не могу найти тегов для вывода статистики по рендерингу страницы. Из Ево сработало часть:
 [^qt^] - время на запросы к базе данных [^q^] - запросов к базе данных [^p^] - время на работу PHP скриптов [^t^] - общее время на генерацию страницы [^s^] - источник содержимого (база или кэш)

 только 2 последних. А мне бы хотелось узнать сколько нужно памяти для рево и время генерации страницы поскольку балуюсь на локалке.
Взялся покопать. Как оказалось, в Эво с этим вообще проблем нет, все отлично выводится. А вот в Рево как бе совсем не все так просто…  
 
В принципе и в Эво и в Рево эти теги остались без именения.
 Вот код Эво:
$out= str_replace("[^q^]", $queries, $out);
$out= str_replace("[^qt^]", $queryTime, $out);
$out= str_replace("[^p^]", $phpTime, $out);
$out= str_replace("[^t^]", $totalTime, $out);
$out= str_replace("[^s^]", $source, $out);
А вот код Рево:
$this->modx->resource->_output= str_replace("[^q^]", $queries, $this->modx->resource->_output);
$this->modx->resource->_output= str_replace("[^qt^]", $queryTime, $this->modx->resource->_output);
$this->modx->resource->_output= str_replace("[^p^]", $phpTime, $this->modx->resource->_output);
$this->modx->resource->_output= str_replace("[^t^]", $totalTime, $this->modx->resource->_output);
$this->modx->resource->_output= str_replace("[^s^]", $source, $this->modx->resource->_output);
Так если все тоже самое, почему не работает?
 
В Эво с этим было проще, так как там на все запросы один единственный класс и по сути единственная центровая функция на выполнение запроса function query($sql).
$tstart = $modx->getMicroTime();
if (!$result = @ mysql_query($sql, $this->conn)) {
   $modx->messageQuit("Execution of a query to the database failed - " . $this->getLastError(), $sql);
} else {
   $tend = $modx->getMicroTime();
   $totaltime = $tend - $tstart;
   $modx->queryTime = $modx->queryTime + $totaltime;
   if ($modx->dumpSQL) {
      $modx->queryCode .= "<fieldset style='text-align:left'><legend>Query " . 
($this->executedQueries + 1) . " - " . sprintf("%2.4f s", $totaltime) . "</legend>" . $sql . "</fieldset><br />";
   }
   $modx->executedQueries = $modx->executedQueries + 1;
   return $result;
}
При чем обратите внимание на то, что если запрос не удалось выполнить, статистика не учитывается (не плюсуются ни счетчик запросов, ни время выполнения), что тоже не есть гуд, но с этим можно смериться.
 
В Рево все оказалось гораздо более запущенно…
 Давайте проследим выполнение одной из функций выборки $modx->getCollection().
 Сам класс modX не имеет этого метода, а наследует его от объекта xPDO.
public function getCollection($className, $criteria= null, $cacheFlag= true) {
        return $this->call($className, 'loadCollection', array(& $this, $className, $criteria, $cacheFlag));
}
В данном случае xPDO не выполняет с ходу запрос, а выполняет данный метод на целевом объекте $className, который в свою очередь напрямую или через несколько колен является расширением от класса xPDOObject. То есть вызывая метод $modx->getCollection('modResource'); мы по сути выполняем modResource->loadCollection();
 К слову, именно поэтому я и говорил, что выдернуть xPDO из MODX Revolution — почти нереал.
 
Ладно, отвлеклись, едем дальше. Смотрим метод xPDOObject::loadCollection();
 Находим там вот это:
$rows= xPDOObject :: _loadRows($xpdo, $className, $criteria);
Вот собственно как раз здесь уже очень близки к месту, где выполняется сам запрос…
 
Смотрим xPDOObject::_loadRows(), и вот как раз здесь все самое интересное...
public static function & _loadRows(& $xpdo, $className, $criteria) {
    $rows= null;
    if ($criteria->prepare()) {
        if ($xpdo->getDebug() === true) $xpdo->log(xPDO::LOG_LEVEL_DEBUG, "Attempting 
to execute query using PDO statement object: " . print_r($criteria->sql, true) . print_r($criteria->bindings, true));
        $tstart= $xpdo->getMicroTime();
        if (!$criteria->stmt->execute()) {
            $tend= $xpdo->getMicroTime();
            $totaltime= $tend - $tstart;
            $xpdo->queryTime= $xpdo->queryTime + $totaltime;
            $xpdo->executedQueries= $xpdo->executedQueries + 1;
            $errorInfo= $criteria->stmt->errorInfo();
            $xpdo->log(xPDO::LOG_LEVEL_ERROR, 'Error ' . $criteria->stmt->errorCode() 
. " executing statement: \n" . print_r($errorInfo, true));
            if (($errorInfo[1] == '1146' || $errorInfo[1] == '1') && 
$xpdo->getOption(xPDO::OPT_AUTO_CREATE_TABLES)) {
                if ($xpdo->getManager() && 
$xpdo->manager->createObjectContainer($className)) {
                    $tstart= $xpdo->getMicroTime();
                    if (!$criteria->stmt->execute()) {
                        $xpdo->log(xPDO::LOG_LEVEL_ERROR, "Error " . 
$criteria->stmt->errorCode() . " executing statement: \n" . print_r($criteria->stmt->errorInfo(), true));
                    }
                    $tend= $xpdo->getMicroTime();
                    $totaltime= $tend - $tstart;
                    $xpdo->queryTime= $xpdo->queryTime + $totaltime;
                    $xpdo->executedQueries= $xpdo->executedQueries + 1;
                } else {
                    $xpdo->log(xPDO::LOG_LEVEL_ERROR, "Error " . $xpdo->errorCode() . 
" attempting to create object container for class {$className}:\n" . 
print_r($xpdo->errorInfo(), true));
                }
            }
        }
        $rows= & $criteria->stmt;
    } else {
        $errorInfo = $xpdo->errorInfo();
        $xpdo->log(xPDO::LOG_LEVEL_ERROR, "Error preparing statement for query: 
{$criteria->sql} - " . print_r($errorInfo, true));
        if (($errorInfo[1] == '1146' || $errorInfo[1] == '1') && 
$xpdo->getOption(xPDO::OPT_AUTO_CREATE_TABLES)) {
            if ($xpdo->getManager() && 
$xpdo->manager->createObjectContainer($className)) {
                if (!$criteria->prepare()) {
                    $xpdo->log(xPDO::LOG_LEVEL_ERROR, "Error preparing statement for query: 
{$criteria->sql} - " . print_r($errorInfo, true));
                } else {
                    $tstart= $xpdo->getMicroTime();
                    if (!$criteria->stmt->execute()) {
                        $xpdo->log(xPDO::LOG_LEVEL_ERROR, "Error " . 
$criteria->stmt->errorCode() . " executing statement: \n" . print_r($criteria->stmt->errorInfo(), true));
                    }
                    $tend= $xpdo->getMicroTime();
                    $totaltime= $tend - $tstart;
                    $xpdo->queryTime= $xpdo->queryTime + $totaltime;
                    $xpdo->executedQueries= $xpdo->executedQueries + 1;
                }
            } else {
                $xpdo->log(xPDO::LOG_LEVEL_ERROR, "Error " . $xpdo->errorCode() . 
" attempting to create object container for class {$className}:\n" . print_r($xpdo->errorInfo(), true));
            }
        }
    }
    return $rows;
}
Специально выдернул всю функцию, дабы лучше показать насколько все запущенно…
 
Первое, на что обратим внимание, это на то, что счетчик запросов и времени исполнения засунут в блок if (!$criteria->stmt->execute()) {}, то есть уже косяк, ибо получается, что счетчик работает только тогда, когда запрос не выполняется, при чем именно из-за SQL-ошибки или типа того. Кстати, сразу забегая вперед, обращаю ваше внимание на то, что именно метод $criteria->stmt->execute() — это и есть метод, который выполняет сам SQL-запрос. Но почему это проблема, раскрою дальше.
 
Подтвердим теорию на практике.
 Создаем пользовательский запрос:
$q = $modx->newQuery('modResource');
$q->where(array(
   'id' => 5,
));
$docs = $modx->getCollection('modResource', $q);
Сразу скажу, что документа с id=5 не существует, потому результат будет нулевой. При этом SQL-ошибки нет, потому и запрос считается выполненным. Выполняем и смотрим результат:
Query Time: 0.0000 s
 Request: 0
 PHP Exec: 0.0760 s
 Total time: 0.0760 s
Теперь испортим наш запрос
$q = $modx->newQuery('modResource');
$q->where(array(
   'idddddddddddddd' => 5,
));
$docs = $modx->getCollection('modResource', $q);
Сами понимаете, что колонки idddddddddddddd в этой таблице нет, а значит будет SQL-ошибка. Выполняем и смотрим:
Query Time: 0.0000 s
 Request: 1
 PHP Exec: 0.0800 s
 Total time: 0.0800 s
То есть выполнен один запрос. Время запроса нулевое скорее всего из-за того, что база пустая, не будем обращать внимание. Если что, пусть кто-нибудь проверит это у себя и отпишется в комменте.
 
Итак, это первый косяк. Попробуем его чуть-чуть исправить и переписать блок функции так:
if ($criteria->prepare()) {
    if ($xpdo->getDebug() === true) $xpdo->log(xPDO::LOG_LEVEL_DEBUG, "Attempting to 
execute query using PDO statement object: " . print_r($criteria->sql, true) . print_r($criteria->bindings, true));
    $tstart= $xpdo->getMicroTime();
    if (!$criteria->stmt->execute()) {
        $errorInfo= $criteria->stmt->errorInfo();
        $xpdo->log(xPDO::LOG_LEVEL_ERROR, 'Error ' . $criteria->stmt->errorCode() . 
" executing statement: \n" . print_r($errorInfo, true));
        if (($errorInfo[1] == '1146' || $errorInfo[1] == '1') && 
$xpdo->getOption(xPDO::OPT_AUTO_CREATE_TABLES)) {
            if ($xpdo->getManager() && $xpdo->manager->createObjectContainer($className)) {
                if (!$criteria->stmt->execute()) {
                    $xpdo->log(xPDO::LOG_LEVEL_ERROR, "Error " . $criteria->stmt->errorCode() . 
" executing statement: \n" . print_r($criteria->stmt->errorInfo(), true));
                }
            } else {
                $xpdo->log(xPDO::LOG_LEVEL_ERROR, "Error " . $xpdo->errorCode() . 
" attempting to create object container for class {$className}:\n" . print_r($xpdo->errorInfo(), true));
            }
        }
    }
    $tend= $xpdo->getMicroTime();
    $totaltime= $tend - $tstart;
    $xpdo->queryTime= $xpdo->queryTime + $totaltime;
    $xpdo->executedQueries= $xpdo->executedQueries + 1;
    $rows= & $criteria->stmt;
}
Мы конечно таким образом не отслеживаем все запросы с учетом ошибок, автосоздания таблиц и т.п., но хотя бы выполненные запросы отслеживаем.
 Проверяем:
Query Time: 0.0000 s
 Request: 7
 PHP Exec: 0.0680 s
 Total time: 0.0680 s
То есть мы видим, что выполнено 7 запросов. Уже что-то.
 
Но, к сожалению, на этом наши беды не заканчиваются…
 Еще проблема:Кто знает xPDO получше, мог в своей практике использовать метод $modx->getCollectionGraph(); Описанным выше путем доходим до того, что это на самом деле метод xPDOObject::loadCollectionGraph();
 Смотрим код функции:
public static function loadCollectionGraph(xPDO & $xpdo, $className, $graph, $criteria, $cacheFlag) {
    $objCollection = array();
    if ($query= $xpdo->newQuery($className, $criteria, $cacheFlag)) {
        $query = $xpdo->addDerivativeCriteria($className, $query);
        $query->bindGraph($graph);
        $rows = array();
        $fromCache = false;
        $collectionCaching = (integer) $xpdo->getOption(xPDO::OPT_CACHE_DB_COLLECTIONS, array(), 1);
        if ($collectionCaching > 0 && $xpdo->_cacheEnabled && $cacheFlag) {
            $rows= $xpdo->fromCache($query);
            $fromCache = !empty($rows);
        }
        if (!$fromCache) {
            if ($query->prepare()) {
                if ($query->stmt->execute()) {
                    $objCollection= $query->hydrateGraph($query->stmt, $cacheFlag);
                } else {
                    $xpdo->log(xPDO::LOG_LEVEL_ERROR, "Error {$query->stmt->errorCode()} executing query: 
{$query->sql} - " . print_r($query->stmt->errorInfo(), true));
                }
            } else {
                $xpdo->log(xPDO::LOG_LEVEL_ERROR, "Error {$xpdo->errorCode()} 
preparing statement: {$query->sql} - " . print_r($xpdo->errorInfo(), true));
            }
        } elseif (!empty($rows)) {
            $objCollection= $query->hydrateGraph($rows, $cacheFlag);
        }
    }
    return $objCollection;
}
И что мы видим? Главное, мы НЕ видим — не видим счетчика запросов и т.п. А это еще один минус по статистике.
 
То есть мы видим, что для разных запросов используются различные методы, которые между собой не пересекаются. Это же касается методов xPDOObject::save(), xPDOObject::remove() и т.п.
 
Продемонстриую еще пример.
 Есть метод xPDO::exec();
public function exec($query) {
    if (!$this->connect(null, array(xPDO::OPT_CONN_MUTABLE => true))) {
        return false;
    }
    $tstart= $this->getMicroTime();
    $return= $this->pdo->exec($query);
    $tend= $this->getMicroTime();
    $totaltime= $tend - $tstart;
    $this->queryTime= $this->queryTime + $totaltime;
    $this->executedQueries= $this->executedQueries + 1;
    return $return;
}
Данный метод выполняет произвольный SQL-запрос.
 Выполним вот это:
$q = $modx->newQuery('modResource');
$q->prepare();
$sql = $q->toSQL();
$modx->exec($sql);
$modx->exec($sql);
$modx->exec($sql);
В данном примере мы генерируем SQL $sql = $q->toSQL() и выполняем его $modx->exec($sql); И да, счетчик запросов щелкает.
Query Time: 0.0040 s
 Request: 10
 PHP Exec: 0.0680 s
 Total time: 0.0720 s
И это хорошо. Но плохо то, что я не видел, чтобы MODX для себя где-то выполнял exec(). Потому можете воткнуть в exec() exit(), и у вас сайт не перестанет работать. То есть сбор статистики здесь мало смысла имеет.
 
«А как же $stmt->execute()? Ведь он же встречается практически во всех перечисленных функциях.» спросят наиболее наблюдательные… А вот здесь как раз и кроется еще одна беда, на которую я намекал выше. Дело в том, что xPDO это расширение от PDO, которое вшито в Си-расширение PHP, и на методы которого напрямую мы не можем воздействовать, а $stmt — это PDOStatement.
 
Таким образом ответ на вопрос пользователя: указанные теги для вывода статистики не потерялись, просто в них информация не актуальная выводится. И чтобы заставить все это дело заработать, придется вклиниться во многие функции xPDO. При чем уверен, здесь не сможет решить этот вопрос ни один модуль для Ревы.
FreeCode.Academy

Статистика количества запросов и времени на исполнение в MODX Revolution

Добавить комментарий
