Николай Ланец
30 июня 2013 г., 14:31

Статистика количества запросов и времени на исполнение в 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. При чем уверен, здесь не сможет решить этот вопрос ни один модуль для Ревы.

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