Штатные средства отладки

В новом ядре D7 появились достаточно удобные встроенные возможности диагностики выполнения кода. Они представлены в пространстве имён Bitrix\Main\Diag.

Вывод содержимого переменной на экран

Bitrix\Main\Diag\Debug::dump(переменная/массив, 'название в выводе', false);

Фактически это надстройка для функции var_dump(), вторым аргументом передаем строку с названием переменной, название будет выведено перед содержимым переменной:

$a = array(
'key1' => 'value1',
'key2' => 'value2',
);
Bitrix\Main\Diag\Debug::dump($a, 'a', false);

Вывод:

a:
array(2) {
["key1"]=>
string(6) "value1"
["key2"]=>
string(6) "value2"
}

Если третий аргумент установлен в true, то метод вернет содержимое переменной вместо вывода на экран.

$a = array(
'key1' => 'value1',
'key2' => 'value2',
);
$www = Bitrix\Main\Diag\Debug::dump($a, 'a', true);
echo $www;

Вывод:

a: array(2) { ["key1"]=> string(6) "value1" ["key2"]=> string(6) "value2" } 

Запись содержимого переменной в файл

Bitrix\Main\Diag\Debug::dumpToFile(переменная/массив, 'название в выводе', 'test.log');

Bitrix\Main\Diag\Debug::writeToFile(переменная/массив, 'название в выводе', 'test.log');

Данные методы позволяют записать содержимое переменной в лог-файл. Путь к файлу относительно корня сайта передается третьим аргументом, по-умолчанию методы пишут в файл test.log в корне сайта.

Метод dumpToFile() пишет в файл результат работы метода Debug::dump(), т.е. в формате функции var_dump(). Метод writeToFile() пишет либо просто значение переменной, либо результат функции print_r(), если переменная является массивом.

Замер времени выполнения кода

Bitrix\Main\Diag\Debug::startTimeLabel('SomeLabel');
// ...некоторые действия...
Bitrix\Main\Diag\Debug::endTimeLabel('SomeLabel');
// далее можно использовать другие метки на других кусках кода
Bitrix\Main\Diag\Debug::dump(Bitrix\Main\Diag\Debug::getTimeLabels());

Вывод:

array(1) {
["SomeLabel"]=>
array(2) {
["start"]=>
float(1536585978.9713)
["time"]=>
float(0.0065689086914062)
}
}

• start время (unix timestamp с микросекундами) первого вызова startTimeLabel;
• time время между startTimeLabel и endTimeLabel в секундах. Если было несколько замеров с одним названием, то время суммируется.

Получение текущей метки времени:

Bitrix\Main\Diag\Helper::getCurrentMicrotime();

Получение стэка вызова функций:

Bitrix\Main\Diag\Helper::getBackTrace($limit = 0, $options = null);

Отладка SQL-запросов

В ядре D7 для отслеживания SQL-запросов используется так называемый SQL-трекер. При использовании трекера при каждом запросе к БД в трекер записывается запрос и время начала и окончания.

$connection = Bitrix\Main\Application::getConnection();
$tracker = $connection->startTracker();
// ...код с выполнением SQL-запросов...
$connection->stopTracker();

После вызова startTracker() и до вызова stopTracker() все запросы будут отслеживаться. Каждый запрос представлен объектом класса Bitrix\Main\Diag\SqlTrackerQuery, коллекцию которых можно получить так:

foreach ($tracker->getQueries() as $query) {
var_dump($query->getSql()); // текст запроса
var_dump($query->getTrace()); // стек вызовов функций
var_dump($query->getTime()); // время выполнения запроса
}

Чтобы очистить данные в трекере и начать новое отслеживание, нужно вызвать startTracker() с аргументом 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' => 5),
)
);
$connection->stopTracker();
// записываем в лог результаты выполнения запроса
foreach ($tracker->getQueries() as $query) {
Bitrix\Main\Diag\Debug::writeToFile(
Bitrix\Main\Diag\Debug::dump($query->getSql(), 'query', true)
);
Bitrix\Main\Diag\Debug::writeToFile(
Bitrix\Main\Diag\Debug::dump($query->getTime(), 'time', true)
);
}

В лог будет записана информация:

query=string(156)
"SELECT 
`iblock_element`.`ID` AS `ID`,
`iblock_element`.`NAME` AS `NAME`
FROM 
`b_iblock_element` `iblock_element` 
WHERE
`iblock_element`.`IBLOCK_ID` = 5"
time=float(0.0017309188842773)