Как узнать какие агенты долго выполняются?

Столкнулся сегодня с обозначенной проблемой. Собственно, раздумывать было особо не о чем.

Понятно, что есть какой-то код, запускающий агентов, и оставалось найти этот код. Выяснилось, что код находится в методе CAgent::ExecuteAgents() в файле /bitrix/modules/main/classes/mysql/agent.php. Разумеется, этот файл относится к файлам ядра и редактировать его можно только если вы понимаете что делаете.

Решение задачи простое: меняем

try
{
	$eval_result = "";
	$e = eval("\$eval_result=".$arAgent["NAME"]);
}

на

try
{
	L('Run: '.$arAgent["NAME"]);
	$Time = microtime(true);
	$eval_result = "";
	$e = eval("\$eval_result=".$arAgent["NAME"]);
	L('End: '.$arAgent["NAME"]);
	L('Time: '.number_format(microtime(true)-$Time,6,'.',''));
	L('From:'.$_SERVER['PHP_SELF'].(!empty($_SERVER['REQUEST_URI'])?' ('.$_SERVER['REQUEST_URI'].')':''));
	L('========================================');
}

Осталось определить функцию логирования для удобной записи в собственный лог, у меня это стандартная функция, применяемая почти на каждом проекте (скопируйте ее в файл /bitrix/php_interface/init.php):

function L($Message){
	if (is_array($Message)) {
		$Message = print_r($Message,1);
	}
	$file_path = $_SERVER['DOCUMENT_ROOT'].'/!log.txt';
	$handle = fopen($file_path, 'a+');
	@flock($handle, LOCK_EX);
	fwrite($handle, '['.date('d.m.Y H:i:s').'] '.$Message."\r\n");
	@flock($handle, LOCK_UN);
	fclose($handle);
}

Все. Теперь при выполнении агентов ваш лог постепенно будет заполняться такими записями:

[17.08.2017 18:37:15] Run: \Bitrix\Main\Analytics\CounterDataTable::submitData();
[17.08.2017 18:37:15] End: \Bitrix\Main\Analytics\CounterDataTable::submitData();
[17.08.2017 18:37:15] Time: 0.041166
[17.08.2017 18:37:15] From:/home/bitrix/www/bitrix/modules/main/tools/cron_events.php
[17.08.2017 18:37:15] ========================================
[17.08.2017 18:39:01] Run: \Bitrix\Sender\MailingManager::checkPeriod();
[17.08.2017 18:39:01] End: \Bitrix\Sender\MailingManager::checkPeriod();
[17.08.2017 18:39:01] Time: 0.014608
[17.08.2017 18:39:01] From:/home/bitrix/www/bitrix/modules/main/tools/cron_events.php
[17.08.2017 18:39:01] ========================================
[17.08.2017 18:39:01] Run: \Bitrix\Main\Analytics\CounterDataTable::submitData();
[17.08.2017 18:39:01] End: \Bitrix\Main\Analytics\CounterDataTable::submitData();
[17.08.2017 18:39:01] Time: 0.006374
[17.08.2017 18:39:01] From:/home/bitrix/www/bitrix/modules/main/tools/cron_events.php
[17.08.2017 18:39:01] ========================================
[17.08.2017 18:40:03] Run: CCaptchaAgent::DeleteOldCaptcha(3600);
[17.08.2017 18:40:03] End: CCaptchaAgent::DeleteOldCaptcha(3600);
[17.08.2017 18:40:03] Time: 0.004447
[17.08.2017 18:40:03] From:/home/bitrix/www/bitrix/modules/main/tools/cron_events.php

Анализируя этот лог, легко понять какие агенты выполняются непозволительно долго.

Все просто. Не забудьте после завершения работы отменить все сделанные изменения. Иначе лог продолжит бесконечно писать ненужные данные, а монитор качества будет ругаться на модифицированные файлы ядра.

Обновлено 2018-11-23.

Просматривая код все того же класса, было найдено более приятное решение данной проблемы, не требующее изменение файлов ядра. Все что требуется - добавить в init.php определение константы, и определение функции. Функция использует для логирования описанную выше фукцию L(), но вы можете использовать свое, хотя бы даже штатное логирование.

define('BX_AGENTS_LOG_FUNCTION', 'AgentsLog');
function AgentsLog($arAgent=false, $strOperation=false, $mEvalResult=false, $mEvalReturn=false){
	$strKey = __FUNCTION__.'_start_time';
	if($strOperation == 'start'){
		$GLOBALS[$strKey] = microtime(true);
		L(sprintf('Start: %s [%s], %s, %s', $arAgent['NAME'], strlen($arAgent['MODULE_ID'])?$arAgent['MODULE_ID']:'--nomodule--', $arAgent['AGENT_INTERVAL'], $arAgent['AGENT_INTERVAL']));
	}
	if($strOperation == 'finish' && isset($GLOBALS[$strKey])){
		L(sprintf('[%s] %s', number_format(microtime(true) - $GLOBALS[$strKey], 4, '.', ''), $arAgent['NAME']));
		unset($GLOBALS[$strKey]);
	}
}