Job has exceeded maximum wall clock time

[IgorPelevanyuk]

Hello,

I faced with very long workload on DIRAC and after 72 hours the jobs finished with the error:
JobWrapper: Job has exceeded maximum wall clock time
How is that possible to increase that time? I was not able to spot the option in my DIRAC Configuration.

[IgorPelevanyuk]

So far, with @atsareg advise I have found an option in SiteDirector MaxQueueLength. I have changed it to bigger value and will be able to tell if it works later.

[IgorPelevanyuk]

It looks like this option did not solve the problem. After 3 days: Job has exceeded maximum wall clock time.

[IgorPelevanyuk]

About Slurm, it should not be a problem since the queue is configured to allow 7 days of a workload:

PARTITION AVAIL  TIMELIMIT  NODES  STATE NODELIST
bmn          up 7-00:00:00     15   idle c5b[22-36]

[IgorPelevanyuk]

I have also checked the log of dirac-pilot on the resource. And it looks like the pilot itself is ok with long workload. It just sees that the workload finished with error after 3 days. And the error is most likely with watchdog, I see the following log line:
Job has exceeded maximum wall clock time of 259200 seconds

The end of the log:

=====================================================================================
Last 8 lines of application output from Watchdog on 2024-07-01 08:14:51.985305 [UTC]:
Last reported CPU consumed for job is 71:02:43 (h:m:s), Batch Queue Time Left 13929055.8 (s @ HS06)
=====================================================================================

WARNING: Parsing of '.cfg' files as command line arguments is changing!
          Set the environment variable 'export DIRAC_NO_CFG=1' to pass the file as a positional
          argument (this will become the default).
          To modify the local configuration use '--cfg <configfile>' instead.
2024-06-28 08:44:44 UTC dirac-jobexec INFO: JobID: 4198220
2024-06-28 08:44:44 UTC dirac-jobexec INFO: DIRAC JobID 4198220 is running at site DIRAC.JINR-LHEP-DDC.ru
Executing StepInstance RunScriptStep1 of type ScriptStep1 ['ScriptStep1']
2024-06-28 08:44:44 UTC dirac-jobexec/Script INFO: Command is: /ceph/bmn/dirac/hdd/DIRAC_m1cvfpvmpilot/4198220/GenToSim.sh /bmn.nica.jinr/vo/gen/DCMSMM/DCMSMM_XeCsI_3.8_AGeV_mb_50k/DCMSMM_XeCsI_3.8_AGeV_mb_50k_97.r12 /bmn.nica.jinr/vo/sim/DCMSMM/DCMSMM_XeCsI_3.8_AGeV_mb_50k/DCMSMM_XeCsI_3.8_AGeV_mb_50k_97.sim.root dev 0 0
2024-07-01 08:44:42 UTC WorkloadManagement/JobAgent/InProcess NOTICE: Pilot Proxy: /ceph/bmn/dirac/hdd/DIRAC_m1cvfpvmpilot/proxy
LoadAvg: 13 MemUsed: 153904.0 kb Job Vsize: 2166796.0 kb Job RSS: 1512876.0 kb DiskSpace: 1712682960.0 MB CPU: 71:32:32 (h:m:s) WallClock: 259202.99 s
Job has exceeded maximum wall clock time of 259200 seconds
Job has exceeded maximum wall clock time
Job has exceeded maximum wall clock time
Last lines of available application output:
================START================
WARNING: Parsing of '.cfg' files as command line arguments is changing!
          Set the environment variable 'export DIRAC_NO_CFG=1' to pass the file as a positional
          argument (this will become the default).
          To modify the local configuration use '--cfg <configfile>' instead.
2024-06-28 08:44:44 UTC dirac-jobexec INFO: JobID: 4198220
2024-06-28 08:44:44 UTC dirac-jobexec INFO: DIRAC JobID 4198220 is running at site DIRAC.JINR-LHEP-DDC.ru
Executing StepInstance RunScriptStep1 of type ScriptStep1 ['ScriptStep1']
2024-06-28 08:44:44 UTC dirac-jobexec/Script INFO: Command is: /ceph/bmn/dirac/hdd/DIRAC_m1cvfpvmpilot/4198220/GenToSim.sh /bmn.nica.jinr/vo/gen/DCMSMM/DCMSMM_XeCsI_3.8_AGeV_mb_50k/DCMSMM_XeCsI_3.8_AGeV_mb_50k_97.r12 /bmn.nica.jinr/vo/sim/DCMSMM/DCMSMM_XeCsI_3.8_AGeV_mb_50k/DCMSMM_XeCsI_3.8_AGeV_mb_50k_97.sim.root dev 0 0
=================END=================
Sending kill signal to application PID 3423899
Subprocess.killChild() returned:9
EXECUTION_RESULT[CPU] after Execution of spObject.systemCall 30.36 15.16 26.15 10.70 259208.03
EXECUTION_RESULT[Thread] after Execution of spObject.systemCall {'OK': True, 'Value': (False, '', '')}
 ==========================================================
Watchdog will report UsageSummary
 ==========================================================
LastUpdateCPU(s) = 257552.0
DiskSpace(MB) = 481312.0
MemoryUsed(kb) = 83996.0
LoadAverage = 41.00779310344827
WallClockTime(s) = 259212.87555789948
ScaledCPUTime(s) = 10394436.309871769
 ==========================================================
Process to monitor has completed, Watchdog will exit.
2024-07-01 08:45:01 UTC None/[4198220]JobWrapper INFO: EXECUTION_RESULT[CPU] in JobWrapper execute 30.36 15.16 26.15 10.70 259208.03
2024-07-01 08:45:01 UTC None/[4198220]JobWrapper INFO: Statistics collected by the Watchdog:
  LastUpdateCPU(s): 257552.0
  DiskSpace(MB): 481312.0
  MemoryUsed(kb): 83996.0
  LoadAverage: 41.00779310344827
  WallClockTime(s): 259212.87555789948
  ScaledCPUTime(s): 10394436.309871769
2024-07-01 08:45:01 UTC None/[4198220]JobWrapper INFO: EXECUTION_RESULT[CPU] in __getCPU 257552.00 15.16 26.15 10.70 259208.03
2024-07-01 08:45:01 UTC None/[4198220]JobWrapper INFO: Total CPU Consumed is: 71:33:24
2024-07-01 08:45:01 UTC None/[4198220]JobWrapper INFO: Normalized CPU Consumed is: 10329920.801
2024-07-01 08:45:01 UTC None/[4198220]JobWrapper INFO:
==================================================================================
Last 8 lines of application output from JobWrapper on 2024-07-01 08:45:01.899941 :
CPU Total: 71:33:24 (h:m:s) Normalized CPU Total 10329920.8 s @ HEP'06
==================================================================================
WARNING: Parsing of '.cfg' files as command line arguments is changing!
          Set the environment variable 'export DIRAC_NO_CFG=1' to pass the file as a positional
          argument (this will become the default).
          To modify the local configuration use '--cfg <configfile>' instead.
2024-06-28 08:44:44 UTC dirac-jobexec INFO: JobID: 4198220
2024-06-28 08:44:44 UTC dirac-jobexec INFO: DIRAC JobID 4198220 is running at site DIRAC.JINR-LHEP-DDC.ru
Executing StepInstance RunScriptStep1 of type ScriptStep1 ['ScriptStep1']
2024-06-28 08:44:44 UTC dirac-jobexec/Script INFO: Command is: /ceph/bmn/dirac/hdd/DIRAC_m1cvfpvmpilot/4198220/GenToSim.sh /bmn.nica.jinr/vo/gen/DCMSMM/DCMSMM_XeCsI_3.8_AGeV_mb_50k/DCMSMM_XeCsI_3.8_AGeV_mb_50k_97.r12 /bmn.nica.jinr/vo/sim/DCMSMM/DCMSMM_XeCsI_3.8_AGeV_mb_50k/DCMSMM_XeCsI_3.8_AGeV_mb_50k_97.sim.root dev 0 0
2024-07-01 08:45:01 UTC None/[4198220]JobWrapper INFO: Checking directory contents after execution:
2024-07-01 08:45:02 UTC None/[4198220]JobWrapper INFO: total 13441870
drwxr-xr-x. 2 ipelevan lcta 13764470248 Jun 28 11:45 .
drwx------. 8 ipelevan lcta 13764847281 Jun 28 11:44 ..
-rw-r--r--. 1 ipelevan lcta         231 Jun 28 11:44 config.cfg
-rw-r--r--. 1 ipelevan lcta  1207082984 Jun 28 11:45 DCMSMM_XeCsI_3.8_AGeV_mb_50k_97.r12
-rw-r--r--. 1 ipelevan lcta         633 Sep 20  2023 fakeload.py
-rw-r--r--. 1 ipelevan lcta    49577776 Jul  1 11:44 gentosim_log.txt
-rwxr-xr-x. 1 ipelevan lcta        4363 May 27 10:18 GenToSim.sh
-rwxr-xr-x. 1 ipelevan lcta        6685 May 27 10:10 jinr-add-file
-rwxr-xr-x. 1 ipelevan lcta        9212 May 27 10:10 jinr-get-file
-rw-r--r--. 1 ipelevan lcta        5013 Jan  1  1970 jobDescription.xml
-rw-r--r--. 1 ipelevan lcta        1132 Jun 28 11:44 job.info
-rwxr-xr-x. 1 ipelevan lcta        3750 May 27 10:11 job_monitoring
-rw-r--r--. 1 ipelevan lcta        1585 Jun 28 11:44 pilot.cfg
-rw-r--r--. 1 ipelevan lcta 12507776024 Jul  1 11:43 sim.root
-rw-r--r--. 1 ipelevan lcta         860 Jun 28 11:44 std.out

2024-07-01 08:45:02 UTC None/[4198220]JobWrapper INFO: Attempting to upload Sandbox with limit: 10485760
2024-07-01 08:45:11 UTC None/[4198220]JobWrapper INFO: Sandbox uploaded successfully
2024-07-01 08:45:11 UTC None/[4198220]JobWrapper INFO: Running JobWrapper finalization
2024-07-01 08:45:11 UTC None/[4198220]JobWrapper INFO: Job finished with errors with no pending requests
2024-07-01 08:45:11 UTC None/[4198220]JobWrapper INFO: Final job status Failed ;
2024-07-01 08:45:11 UTC None/[4198220]JobWrapper INFO: EXECUTION_RESULT[CPU] in sendJobAccounting 257552.00 15.16 26.15 10.70 259208.03
2024-07-01 08:45:12 UTC WorkloadManagement/JobAgent/InProcess WARN: Fail in payload execution
2024-07-01 08:45:12 UTC WorkloadManagement/JobAgent/InProcess INFO: Exit status: 1
2024-07-01 08:45:12 UTC WorkloadManagement/JobAgent/WorkloadManagement/JobAgent INFO: Job being submitted (DIRAC JobID: 4198220; Task ID: 0)
2024-07-01 08:45:22 UTC WorkloadManagement/JobAgent/WorkloadManagement/JobAgent INFO: Payload execution failed with error code 1
2024-07-01 08:45:22 UTC WorkloadManagement/JobAgent/WorkloadManagement/JobAgent INFO: JobAgent will stop with message "Error during a payload execution", execution complete.
2024-07-01 08:45:22 UTC WorkloadManagement/JobAgent/WorkloadManagement/JobAgent NOTICE: ----------------------------------------
2024-07-01 08:45:22 UTC WorkloadManagement/JobAgent/WorkloadManagement/JobAgent NOTICE: Agent module WorkloadManagement/JobAgent run summary
2024-07-01 08:45:22 UTC WorkloadManagement/JobAgent/WorkloadManagement/JobAgent NOTICE:  Executed 1 times previously
2024-07-01 08:45:22 UTC WorkloadManagement/JobAgent/WorkloadManagement/JobAgent NOTICE:  Cycle took 259241.83 seconds
2024-07-01 08:45:22 UTC WorkloadManagement/JobAgent/WorkloadManagement/JobAgent NOTICE:  Average execution time: 259241.83 seconds
2024-07-01 08:45:22 UTC WorkloadManagement/JobAgent/WorkloadManagement/JobAgent NOTICE:  Polling time: 20 seconds
2024-07-01 08:45:22 UTC WorkloadManagement/JobAgent/WorkloadManagement/JobAgent NOTICE:  Average execution/polling time: 1296209.17%
2024-07-01 08:45:22 UTC WorkloadManagement/JobAgent/WorkloadManagement/JobAgent WARN:  Cycle had an error: Error during a payload execution
2024-07-01 08:45:22 UTC WorkloadManagement/JobAgent/WorkloadManagement/JobAgent NOTICE: ----------------------------------------
2024-07-01 08:45:22 UTC WorkloadManagement/JobAgent INFO: No more agent modules to execute. Exiting

2024-07-01T08:45:22.928307Z INFO [LaunchAgent] DiskSpace (MB) = 1712850372

[andresailer]

Please use triple tick marks
```
my
log
dump
```

[aldbr]

In your CS, have you set any value for /Systems/WorkloadManagement/<setup>/JobWrapper/MaxWallClockTime?
By default, it seems to be 3 days (72 hours).
Could you try to increase this value?

[IgorPelevanyuk]

No, there is no such section in my configuration. I will try to do that!

[IgorPelevanyuk]

Option added. On Friday I will be able to tell if it works.

[IgorPelevanyuk]

Jobs failed. I mistakenly thought that JobWrapper conficuration should be in Agents. I have changed the placement of the JobWrapper configuration to be in Systems/WorkloadManagement/Production/JobWrapper.
Trying this. Results will be on Monday.

[aldbr]

Oops yes indeed I did not check properly your configuration. Your new configuration is correct. Let's see how it goes 🤞

[IgorPelevanyuk]

So far the jobs are working smoothly! It looks like this solution is working!

In your CS, have you set any value for /Systems/WorkloadManagement/<setup>/JobWrapper/MaxWallClockTime? By default, it seems to be 3 days (72 hours). Could you try to increase this value?

[IgorPelevanyuk]

@aldbr Thank you!