From a0761a079baabb9d2270dcbf999fc294282fab54 Mon Sep 17 00:00:00 2001 From: Eric Espie Date: Fri, 18 Nov 2022 23:41:13 +0100 Subject: [PATCH] Cron parallelization * better logs --- setup/compiler.class.inc.php | 2 ++ setup/setuputils.class.inc.php | 37 ++++++++++++++++---------------- sources/Service/Cron/CronLog.php | 17 +++++++++++++++ webservices/cron.php | 24 +++++++++++++++------ 4 files changed, 55 insertions(+), 25 deletions(-) diff --git a/setup/compiler.class.inc.php b/setup/compiler.class.inc.php index a9394931a..8e71d1b55 100644 --- a/setup/compiler.class.inc.php +++ b/setup/compiler.class.inc.php @@ -317,10 +317,12 @@ class MFCompiler try { + SetupLog::Info("Compiling $sTempTargetDir..."); $this->DoCompile($sTempTargetDir, $sFinalTargetDir, $oP = null, $bUseSymbolicLinks); } catch (Exception $e) { + SetupLog::Info("Compiling error: ".$e->getMessage()); if ($sTempTargetDir != $sFinalTargetDir) { // Cleanup the temporary directory diff --git a/setup/setuputils.class.inc.php b/setup/setuputils.class.inc.php index 3213195d7..6ad4534ef 100644 --- a/setup/setuputils.class.inc.php +++ b/setup/setuputils.class.inc.php @@ -2038,8 +2038,10 @@ JS */ private static function WaitCronTermination($oConfig, $sMode) { - try - { + $iMaxDuration = $oConfig->Get('cron_max_execution_time'); + // Avoid PHP stopping while waiting the cron + set_time_limit($iMaxDuration); + try { // Wait for cron to stop if (is_null($oConfig) || ContextTag::Check(ContextTag::TAG_CRON)) { return; @@ -2047,7 +2049,6 @@ JS // Limit the number of cron process to run in parallel $iMaxCronProcess = $oConfig->Get('cron.max_processes'); $iCount = 1; - $iMaxDuration = $oConfig->Get('cron_max_execution_time'); $iTimeLimit = time() + $iMaxDuration; do { $bIsRunning = false; @@ -2055,26 +2056,26 @@ JS for ($i = 0; $i < $iMaxCronProcess; $i++) { $sName = "cron#$i"; - $oMutex = new iTopMutex( + $oMutex = new iTopMutex( $sName.$oConfig->Get('db_name').$oConfig->Get('db_subname'), - $oConfig->Get('db_host'), - $oConfig->Get('db_user'), - $oConfig->Get('db_pwd'), - $oConfig->Get('db_tls.enabled'), - $oConfig->Get('db_tls.ca') - ); + $oConfig->Get('db_host'), + $oConfig->Get('db_user'), + $oConfig->Get('db_pwd'), + $oConfig->Get('db_tls.enabled'), + $oConfig->Get('db_tls.ca') + ); if ($oMutex->IsLocked()) { $bIsRunning = true; - SetupLog::Info("Waiting for cron to stop ($iCount)"); - $iCount++; - sleep(1); - if (time() > $iTimeLimit) - { - throw new Exception("Cannot enter $sMode mode, consider stopping the cron temporarily"); - } + SetupLog::Info("Waiting for cron to stop ($iCount)"); + $iCount++; + sleep(1); + if (time() > $iTimeLimit) { + SetupLog::Error("Cannot enter $sMode mode, consider stopping the cron temporarily"); + throw new Exception("Cannot enter $sMode mode, consider stopping the cron temporarily"); + } break; } - } + } } while ($bIsRunning); } catch (Exception $e) { diff --git a/sources/Service/Cron/CronLog.php b/sources/Service/Cron/CronLog.php index 857e0cc26..7ef326034 100644 --- a/sources/Service/Cron/CronLog.php +++ b/sources/Service/Cron/CronLog.php @@ -7,10 +7,13 @@ namespace Combodo\iTop\Service\Cron; use LogAPI; +use Page; class CronLog extends LogAPI { public static $iProcessNumber = 0; + private static $bDebug = false; + private static $oP = null; const CHANNEL_DEFAULT = 'Cron'; /** @@ -27,4 +30,18 @@ class CronLog extends LogAPI $sMessage = 'cron'.str_pad(static::$iProcessNumber, 3).$sMessage; parent::Log($sLevel, $sMessage, $sChannel, $aContext); } + + public static function Debug($sMessage, $sChannel = null, $aContext = array()) + { + if (self::$bDebug && self::$oP) { + self::$oP->p('cron'.str_pad(static::$iProcessNumber, 3).$sMessage); + } + parent::Debug($sMessage, $sChannel, $aContext); + } + + public static function SetDebug(Page $oP, $bDebug) + { + self::$oP = $oP; + self::$bDebug = $bDebug; + } } \ No newline at end of file diff --git a/webservices/cron.php b/webservices/cron.php index 58ebc83d7..9f416f20d 100644 --- a/webservices/cron.php +++ b/webservices/cron.php @@ -208,10 +208,8 @@ function CronExec($bDebug) $oTasks = new DBObjectSet($oSearch, ['next_run_date' => true]); $aTasks = []; - if ($oTasks->CountExceeds(0)) - { - $sCount = $oTasks->Count(); - CronLog::Debug("$sCount Tasks planned to run now ($sNow):"); + if ($oTasks->CountExceeds(0)) { + $aDebugMessages = []; while ($oTask = $oTasks->Fetch()) { $sTaskName = $oTask->Get('class_name'); @@ -224,7 +222,12 @@ function CronExec($bDebug) $sStatus = $oTask->Get('status'); $sLastRunDate = $oTask->Get('latest_run_date'); $sNextRunDate = $oTask->Get('next_run_date'); - CronLog::Debug(sprintf('Task Class: %1$-25.25s Status: %2$-7s Last Run: %3$-19s Next Run: %4$-19s', $sTaskName, $sStatus, $sLastRunDate, $sNextRunDate)); + $aDebugMessages[] = sprintf('Task Class: %1$-25.25s Status: %2$-7s Last Run: %3$-19s Next Run: %4$-19s', $sTaskName, $sStatus, $sLastRunDate, $sNextRunDate); + } + $sCount = count($aDebugMessages); + CronLog::Debug("$sCount Tasks planned to run now ($sNow):"); + foreach ($aDebugMessages as $sDebugMessage) { + CronLog::Debug($sDebugMessage); } $aRunTasks = []; while ($aTasks != []) { @@ -268,7 +271,7 @@ function CronExec($bDebug) } $oEnd = new DateTime(); $sNextRunDate = $oTask->Get('next_run_date'); - CronLog::Debug("<< === ".$oEnd->format('Y-m-d H:i:s').sprintf(" End of: %-'=42s", ' '.$sTaskClass.' ')." Next: $sNextRunDate"); + CronLog::Debug("<< === ".$oEnd->format('Y-m-d H:i:s').sprintf(" End of: %-'=49s", ' '.$sTaskClass.' ')." Next: $sNextRunDate"); if (time() > $iTimeLimit) { break 2; @@ -297,6 +300,7 @@ function CronExec($bDebug) } } if (count($aTasks) == 0) { + CronLog::Debug("sleeping..."); sleep($iCronSleep); } } @@ -454,6 +458,11 @@ try { utils::UseParamFile(); + // Allow verbosity on output (writing debug messages to the cron.log file is configured with log_level_min config parameter) + $bVerbose = utils::ReadParam('verbose', false, true /* Allow CLI */); + CronLog::SetDebug($oP, $bVerbose); + + // Used to launch the BackgroundTask in debug mode $bDebug = utils::ReadParam('debug', false, true /* Allow CLI */); if ($bIsModeCLI) @@ -530,7 +539,8 @@ try CronLog::Info('Starting: '.time().' ('.date('Y-m-d H:i:s').')'); CronExec($bDebug); } else { - CronLog::Debug("Already $iMaxCronProcess are running..."); + CronLog::$iProcessNumber = $iMaxCronProcess + 1; + CronLog::Debug("The limit of $iMaxCronProcess cron process running in parallel is already reached"); } } }