01.07.2019

Возможности отладки Bitrix D7

В ядре 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() возвращает стек вызовов функций.

Ссылка на оригинал блог mrcappuccino.ru Возможности отладки в Битрикс D7