В ядре D7 появились относительно удобные встроенные возможности диагностики выполнения кода. Они представлены в пространстве имён Bitrix\Main\Diag, в дальнейших примерах используется сокращение:
use Bitrix\Main\Diag;
Отладка SQL-запросов
В ядре D7 для отслеживания SQL-запросов используется так называемый SQL-трекер. При использовании трекера при каждом запросе к БД (метод Bitrix\Main\DB\Connection::queryInternal) в трекер записывается запрос и время начала и окончания. Трекер является объектом класса Diag\SqlTracker.
Для получения трекера и включения отслеживания нужно получить объект текущего соединения и вызвать метод startTracker:
$connection = Bitrix\Main\Application::getConnection();
/** Bitrix\Main\Diag\SqlTracker $tracker */
$tracker = $connection->startTracker();
// ...
$connection->stopTracker();
После вызова startTracker до вызова stopTracker все запросы будут отслеживаться. Каждый запрос представлен объектом класса Bitrix\Main\Diag\SqlTrackerQuery, коллекцию которых можно получить вызвав метод Diag\SqlTracker::getQueries
foreach ($tracker->getQueries() as $query) {
var_dump($query->getSql()); // Текст запроса
var_dump($query->getTrace()); // Стек вызовов функций, которые привели к выполнению запроса
var_dump($query->getTime()); // Время выполнения запроса в секундах
}
Для того, чтобы очистить данные в трекере и начать новое отслеживание, нужно вызвать startTracker с аргументом $reset = true:
$tracker = $connection->startTracker(true);
Пример отслеживания запросов при получении элементов инфоблока:
Bitrix\Main\Loader::includeModule("iblock");
$connection = Bitrix\Main\Application::getConnection();
$tracker = $connection->startTracker();
$query = Bitrix\Iblock\ElementTable::getList(array(
'select' => array('ID', 'NAME'),
'filter' => array('IBLOCK_ID' => 2),
));
$connection->stopTracker();
foreach ($tracker->getQueries() as $query) {
var_dump($query->getSql());
var_dump($query->getTime());
}
Выведет:
string(156) "SELECT
`iblock_element`.`ID` AS `ID`,
`iblock_element`.`NAME` AS `NAME`
FROM `b_iblock_element` `iblock_element`
WHERE `iblock_element`.`IBLOCK_ID` = 2"
float(0.0006859302520752)
Следует учесть, что этот трекер не отслеживает запросы, сделанные через старое ядро.
Вывод содержимого переменной на экран
Diag\Debug::dump($var, $varName = "", $return = false)
Diag\Debug::dump позволяет вывести содержимое переменной в читаемом виде, фактически это надстройка для var_dump:
$a = array(
"key" => "value",
"key2" => "value2",
);
Diag\Debug::dump($a);
/*
Выведет на экран:
array(2) {
["key"]=>
string(5) "value"
["key2"]=>
string(6) "value2"
}
*/
Если вторым аргументов передать строку с названием переменной, то оно будет выведено перед содержимым переменной:
$a = array(
"key" => "value",
"key2" => "value2",
);
Diag\Debug::dump($a, "a");
/*
Выведет на экран:
a:
array(2) {
["key"]=>
string(5) "value"
["key2"]=>
string(6) "value2"
}
*/
Если третий аргумент установлен в true, то метод вернет содержимое переменной вместо вывода на экран.
Дамп содержимого переменной в файл
Diag\Debug::dumpToFile($var, $varName = "", $fileName = "")
Diag\Debug::writeToFile($var, $varName = "", $fileName = "")
Данные функции позволяют записать содержимое переменной в лог-файл. Путь к файлу относительно коря сайта передается третим аргументом $fileName, по-умолчанию методы пишут в файл /__bx_log.log.
dumpToFile пишет в файл результат работы метода Debug::dump, т.е. в формате функции var_dump. writeToFile же пишет либо просто значение переменной, либо результат функции print_r, если переменная является массивом.
Замер времени выполнения кода
Если нужно замерить время выполнения некоторого куска кода, можно воспользоваться таким встроенным решением:
Diag\Debug::startTimeLabel("label1");
// ...некоторые действия...
Diag\Debug::endTimeLabel("label1");
// далее можем использовать другие метки на других кусках кода
Diag\Debug::dump(Debug::getTimeLabels());
/*
Выведет на экран:
array(1) {
["label1"]=>
array(2) {
["start"]=>
float(1473415593.0706)
["time"]=>
float(1.215934753418E-5)
}
}
*/
start - время(unix timestamp с микросекундами) первого вызова startTimeLabel.
time - время между startTimeLabel и endTimeLabel в секундах. Если было несколько замеров с одним названием (в примере – "label1"), то время суммируется.
Бонус
Также есть два полезных метода для диагностики в классе Bitrix\Main\Diag\Helper:
Diag\Helper::getCurrentMicrotime() возвращает текущую метку времени с микросекундами.
Diag\Helper::getBackTrace() возвращает стек вызовов функций.