N°4692 - Enable parallelization of multiple CRON jobs #304

eespie · 2022-07-04T11:28:08Z

Allow cron process to execute in parallel running different tasks.

Each task is only executed once at a time, but different tasks can run in parallel if multiple cron are executed.
The maximum number of parallel cron processes is configurable in iTop configuration.

The number of concurrent cron processes is obtained by configuring the 'cron_max_execution_time' and playing with the period of the cron. For example if the cron process last 10 minutes and the cron is launched every minute there will be roughly 10 parallel cron running.

Another change is that the 'next_run_date' is calculated before running the task in order to have an update in case of problem and avoid running the same task again and again.

Hipska

Looks good. Plain simple implementation!

Hipska · 2022-07-04T15:39:44Z

webservices/cron.php

-		if ($bVerbose && $bWorkDone)
-		{
-			$oP->p("Sleeping...\n");
+		if ($aTasks == []) {


Wouldn't it be better to do this?

Suggested change

if ($aTasks == []) {

if (empty($aTasks)) {

Yes, but we rather use count($aTasks) === 0 than empty()

core/config.class.inc.php

setup/setuputils.class.inc.php

webservices/cron.php

Molkobain · 2022-07-05T14:38:59Z

webservices/cron.php

 			}

 			// Tasks to run later
-			if ($bVerbose)
+			if ($bVerbose && $aTasks == [])


Molkobain · 2022-07-05T14:41:49Z

@eespie will:

Create the corresponding bug in the bug tracker.
Discuss with @Rorcha07 about it
Study debug / verbose output when several CRON instances are running, which could be an issue when trying to debug something

sources/Service/Cron/CronLog.php

Molkobain · 2022-08-17T11:13:18Z

webservices/cron.php

-					$sNextRunDate = $oTask->Get('next_run_date');
-					$oP->p(sprintf('| %1$-25.25s | %2$-7s | %3$-19s | %4$-19s |', $sTaskName, $sStatus, $sLastRunDate, $sNextRunDate));
-				}
-			}
-			if ($bVerbose)
-			{
-				$oP->p('+---------------------------+---------+---------------------+---------------------+');
+				$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));


Can you give an example of output? Seems more complicated to read than the previous way as there will be no columns anymore.

The debug array has been removed because when logs are interleaved it's more complicated to read.
Here is a run of one cron instance:

cron1 3 Tasks planned to run now (2022-11-18 23:02:29): cron1 Task Class: InlineImageGC Status: active Last Run: 2022-11-18 23:02:27 Next Run: 2022-11-18 23:02:28 cron1 Task Class: ExecAsyncTask Status: active Last Run: 2022-11-18 23:02:27 Next Run: 2022-11-18 23:02:29 cron1 Task Class: PersonalDataAnonymizer Status: active Last Run: 2022-11-18 23:02:29 Next Run: 2022-11-18 23:02:29 cron1 >> === 2022-11-18 23:02:29 Start task: InlineImageGC ================================== cron1 InlineImageGC: Cleaned 0 old temporary InlineImage(s) and 0 old temporary Attachment(s). cron1 << === 2022-11-18 23:02:29 End of: InlineImageGC ================================== Next: 2022-11-18 23:02:30 cron1 2 Tasks planned to run now (2022-11-18 23:02:29): cron1 Task Class: ExecAsyncTask Status: active Last Run: 2022-11-18 23:02:27 Next Run: 2022-11-18 23:02:29 cron1 Task Class: PersonalDataAnonymizer Status: active Last Run: 2022-11-18 23:02:29 Next Run: 2022-11-18 23:02:29 cron1 >> === 2022-11-18 23:02:29 Start task: ExecAsyncTask ================================== cron1 ExecAsyncTask: processed 0 tasks cron1 << === 2022-11-18 23:02:29 End of: ExecAsyncTask ================================== Next: 2022-11-18 23:02:31 cron1 1 Tasks planned to run now (2022-11-18 23:02:29): cron1 Task Class: PersonalDataAnonymizer Status: active Last Run: 2022-11-18 23:02:29 Next Run: 2022-11-18 23:02:29 cron1 >> === 2022-11-18 23:02:29 Start task: PersonalDataAnonymizer ========================= cron1 << === 2022-11-18 23:02:29 End of: PersonalDataAnonymizer ========================= Next: 2022-11-18 23:02:29 cron1 -- Skipping task: InlineImageGC -------------------------- until: 2022-11-18 23:02:30 cron1 -- Skipping task: ExecAsyncTask -------------------------- until: 2022-11-18 23:02:31 cron1 -- Skipping task: CheckStopWatchThresholds --------------- until: 2022-11-18 23:02:33 cron1 -- Skipping task: FullTextBackgroundRefresh -------------- until: 2022-11-18 23:02:43 cron1 -- Skipping task: ObsolescenceDateUpdater ---------------- until: 2022-11-18 23:12:07 cron1 -- Skipping task: BulkExportResultGC --------------------- until: 2022-11-19 11:12:51 cron1 -- Skipping task: FullTextBackgroundRebuildFullIndex ----- until: 2022-11-20 01:30:00 cron1 -- Skipping task: LogFileRotationProcess ----------------- until: 2022-12-01 00:00:00 cron1 -- Skipping task: BackupExec ----------------------------- until: 3000-01-01 00:00:00 cron1 sleeping...

An interleaved example (yes it's hard to follow):

2022-11-18 23:41:23 | Debug | 1 | cron1 4 Tasks planned to run now (2022-11-18 23:41:23): | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron2 4 Tasks planned to run now (2022-11-18 23:41:23): | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron1 Task Class: PersonalDataAnonymizer Status: active Last Run: 2022-11-18 23:41:21 Next Run: 2022-11-18 23:41:21 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron2 Task Class: PersonalDataAnonymizer Status: active Last Run: 2022-11-18 23:41:21 Next Run: 2022-11-18 23:41:21 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron1 Task Class: InlineImageGC Status: active Last Run: 2022-11-18 23:41:21 Next Run: 2022-11-18 23:41:22 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron2 Task Class: InlineImageGC Status: active Last Run: 2022-11-18 23:41:21 Next Run: 2022-11-18 23:41:22 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron1 Task Class: ExecAsyncTask Status: active Last Run: 2022-11-18 23:41:21 Next Run: 2022-11-18 23:41:23 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron2 Task Class: ExecAsyncTask Status: active Last Run: 2022-11-18 23:41:21 Next Run: 2022-11-18 23:41:23 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron1 Task Class: CheckStopWatchThresholds Status: active Last Run: 2022-11-18 23:41:13 Next Run: 2022-11-18 23:41:23 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron2 Task Class: CheckStopWatchThresholds Status: active Last Run: 2022-11-18 23:41:13 Next Run: 2022-11-18 23:41:23 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron2 >> === 2022-11-18 23:41:23 Start task: PersonalDataAnonymizer ========================= | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron1 >> === 2022-11-18 23:41:23 Start task: InlineImageGC ================================== | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron1 InlineImageGC: Cleaned 0 old temporary InlineImage(s) and 0 old temporary Attachment(s). | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron1 << === 2022-11-18 23:41:23 End of: InlineImageGC ================================== Next: 2022-11-18 23:41:24 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron2 << === 2022-11-18 23:41:23 End of: PersonalDataAnonymizer ========================= Next: 2022-11-18 23:41:23 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron1 3 Tasks planned to run now (2022-11-18 23:41:23): | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron1 Task Class: ExecAsyncTask Status: active Last Run: 2022-11-18 23:41:21 Next Run: 2022-11-18 23:41:23 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron1 Task Class: CheckStopWatchThresholds Status: active Last Run: 2022-11-18 23:41:13 Next Run: 2022-11-18 23:41:23 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron1 Task Class: PersonalDataAnonymizer Status: active Last Run: 2022-11-18 23:41:23 Next Run: 2022-11-18 23:41:23 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron4 3 Tasks planned to run now (2022-11-18 23:41:23): | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron4 Task Class: ExecAsyncTask Status: active Last Run: 2022-11-18 23:41:21 Next Run: 2022-11-18 23:41:23 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron4 Task Class: CheckStopWatchThresholds Status: active Last Run: 2022-11-18 23:41:13 Next Run: 2022-11-18 23:41:23 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron1 >> === 2022-11-18 23:41:23 Start task: ExecAsyncTask ================================== | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron4 Task Class: PersonalDataAnonymizer Status: active Last Run: 2022-11-18 23:41:23 Next Run: 2022-11-18 23:41:23 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron2 3 Tasks planned to run now (2022-11-18 23:41:23): | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron2 Task Class: ExecAsyncTask Status: active Last Run: 2022-11-18 23:41:21 Next Run: 2022-11-18 23:41:23 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron2 Task Class: CheckStopWatchThresholds Status: active Last Run: 2022-11-18 23:41:13 Next Run: 2022-11-18 23:41:23 | Cron ||| 2022-11-18 23:41:23 | Debug | 1 | cron2 Task Class: PersonalDataAnonymizer Status: active Last Run: 2022-11-18 23:41:23 Next Run: 2022-11-18 23:41:23 | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron1 ExecAsyncTask: processed 0 tasks | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron1 << === 2022-11-18 23:41:24 End of: ExecAsyncTask ================================== Next: 2022-11-18 23:41:25 | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron4 >> === 2022-11-18 23:41:24 Start task: CheckStopWatchThresholds ======================= | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron2 >> === 2022-11-18 23:41:24 Start task: ExecAsyncTask ================================== | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron1 2 Tasks planned to run now (2022-11-18 23:41:24): | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron1 Task Class: PersonalDataAnonymizer Status: active Last Run: 2022-11-18 23:41:23 Next Run: 2022-11-18 23:41:23 | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron1 Task Class: InlineImageGC Status: active Last Run: 2022-11-18 23:41:23 Next Run: 2022-11-18 23:41:24 | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron2 ExecAsyncTask: processed 0 tasks | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron2 << === 2022-11-18 23:41:24 End of: ExecAsyncTask ================================== Next: 2022-11-18 23:41:25 | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron1 >> === 2022-11-18 23:41:24 Start task: PersonalDataAnonymizer ========================= | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron2 1 Tasks planned to run now (2022-11-18 23:41:24): | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron2 Task Class: InlineImageGC Status: active Last Run: 2022-11-18 23:41:23 Next Run: 2022-11-18 23:41:24 | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron2 >> === 2022-11-18 23:41:24 Start task: InlineImageGC ================================== | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron2 InlineImageGC: Cleaned 0 old temporary InlineImage(s) and 0 old temporary Attachment(s). | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron2 << === 2022-11-18 23:41:24 End of: InlineImageGC ================================== Next: 2022-11-18 23:41:25 | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron2 -- Skipping task: ExecAsyncTask -------------------------- until: 2022-11-18 23:41:25 | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron2 -- Skipping task: CheckStopWatchThresholds --------------- until: 2022-11-18 23:41:33 | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron2 -- Skipping task: FullTextBackgroundRefresh -------------- until: 2022-11-18 23:41:43 | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron2 -- Skipping task: ObsolescenceDateUpdater ---------------- until: 2022-11-18 23:42:07 | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron2 -- Skipping task: BulkExportResultGC --------------------- until: 2022-11-19 11:12:51 | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron2 -- Skipping task: FullTextBackgroundRebuildFullIndex ----- until: 2022-11-20 01:30:00 | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron2 -- Skipping task: LogFileRotationProcess ----------------- until: 2022-12-01 00:00:00 | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron2 -- Skipping task: BackupExec ----------------------------- until: 3000-01-01 00:00:00 | Cron ||| 2022-11-18 23:41:24 | Debug | 1 | cron2 sleeping... | Cron |||

webservices/cron.php

Molkobain · 2022-08-17T11:25:59Z

webservices/cron.php

 		} else {
-			$oP->p("Already $iMaxCronProcess are running...");
+			CronLog::Debug("Already $iMaxCronProcess are running...");


Having "Already 5 are running..." in the log might not be clear to understand for someone troubleshooting/browsing the logs if it doesn't know the code.

What do you think of "Already 5/5 CRON processes are running, cannot start another one..." (or something similar) ?

webservices/cron.php

Hipska · 2022-08-22T10:21:38Z

webservices/cron.php

+			$sCount = $oTasks->Count();
+			CronLog::Debug("$sCount Tasks planned to run now ($sNow):");
 			while ($oTask = $oTasks->Fetch())
 			{
-				$aTasks[$oTask->Get('class_name')] = $oTask;
-				if ($bVerbose)
-				{
-					$sTaskName = $oTask->Get('class_name');
-					$sStatus = $oTask->Get('status');
-					$sLastRunDate = $oTask->Get('latest_run_date');
-					$sNextRunDate = $oTask->Get('next_run_date');
-					$oP->p(sprintf('| %1$-25.25s | %2$-7s | %3$-19s | %4$-19s |', $sTaskName, $sStatus, $sLastRunDate, $sNextRunDate));
+				$sTaskName = $oTask->Get('class_name');
+				$oTaskMutex = new iTopMutex("cron_$sTaskName");
+				if ($oTaskMutex->IsLocked()) {
+					// Already running, ignore
+					continue;
 				}
-			}
-			if ($bVerbose)
-			{
-				$oP->p('+---------------------------+---------+---------------------+---------------------+');
+				$aTasks[] = $oTask;
+				$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));
 			}


I also think we have a mismatch with number of tasks planned and the number of tasks displayed. (When a tasks unable to get a mutex lock.)

Hipska · 2022-08-22T10:22:45Z

webservices/cron.php

+			while ($aTasks != []) {
+				$oTask = array_shift($aTasks);


Why not a simple foreach? Also, might be better to use count($aTasks).

Edit: Just saw that was originally the case..

Hipska · 2022-11-18T10:24:36Z

core/config.class.inc.php

-		'cron_task_max_execution_time' => [
-			'type' => 'integer',
-			'description' => 'Background tasks will use this value (integer) multiplicated by its periodicity (in seconds) as max duration per cron execution. 0 is unlimited time',
-			'default' => 0,
-			'value' => 0,
-			'source_of_value' => '',
-			'show_in_conf_sample' => false,
-		],


cron_task_max_execution_time is a setting that should stay I assume?

Well, the parameter will stay, but the behaviour will change (the « multiplicated by its periodicity (in seconds) » part is not pertinent anymore)

Okay, but the current state of this PR just removes this setting parameter. Or did I miss something?

In fact 'cron_max_execution_time' is yet used, but 'cron_task_max_execution_time' is not used anymore... sorry for the confusion. The limit of execution of one task is the remaining cron execution time as it won't block other tasks anymore.
I'm sorry this project is pretty old now, and I'm not sure it will be integrated soon :(

* Setup wait for multiple cron processes * Avoid waiting while tasks must be run

Co-authored-by: Molkobain <[email protected]>

* refactor counts

* refactor logs

Co-authored-by: Molkobain <[email protected]>

Hipska · 2023-01-09T10:08:38Z

webservices/cron.php

-			foreach ($aTasks as $oTask)
-			{
+			while (count($aTasks) > 0) {
+				$oTask = array_shift($aTasks);


Why this change?

eespie self-assigned this Jul 4, 2022

eespie requested review from piRGoif and Molkobain July 4, 2022 11:28

eespie added enhancement New feature or request core R&D team review needed modernization labels Jul 4, 2022

piRGoif added internal Work made by Combodo and removed R&D team review needed labels Jul 4, 2022

Hipska approved these changes Jul 4, 2022

View reviewed changes