Development for LHC@home

Yes Ray,
something went wrong with -dev and production-tasks.
Have deleted .vdi of Atlas from -dev
VBoxManage.exe: error: Could not find file for the medium

'C:\ProgramData\BOINC\projects\lhcathomedev.cern.ch_lhcathome-dev\ATLAS_vbox_1.13_image.vdi' (VERR_FILE_NOT_FOUND).

and waiting for the end of three CMS-Tasks (about three hours).

Then making a reset of the -dev Project and hoping all is ok.
Using for both vboxwrapper 204 (in production renamed the wrapper).
https://lhcathomedev.cern.ch/lhcathome-dev/result.php?resultid=3097402

Strange behaviour of three tasks so far waiting for: *** Job finished ***
https://lhcathomedev.cern.ch/lhcathome-dev/result.php?resultid=3097299
https://lhcathomedev.cern.ch/lhcathome-dev/result.php?resultid=3097310
https://lhcathomedev.cern.ch/lhcathome-dev/result.php?resultid=3097320

Very long runtimes. After the 20 events were ready, 'Preparing HITS file was displayed for almost 2 hours.
I forced the first task to start from scratch. The second task was restarted after a suspend and the 3rd was in a running state all the time.
After >2 hours they finished and uploaded a result file.

I checked the full logs and there is a strange timeshift in the middle of the task:

2022-07-04 18:42:41,307 | INFO     | executing command: export ATLAS_LOCAL_ROOT_BASE=/cvmfs/atlas.cern.ch/repo/ATLASLocalRootBase;source ${ATLAS_LOCAL_ROOT_BASE}/user/atlasLocalSetup.sh --quiet;source $AtlasSetup/scripts/asetup.sh AtlasOffline,21.0.15,notest --platform x86_64-slc6-gcc49-opt --makeflags='$MAKEFLAGS'
2022-07-04 16:43:00,181 | INFO     | nothing to verify (for remote files)

Did you change the system time or something like that? This could have confused the software into hanging until the time "caught up" with the previous time:

2022-07-04 18:40:12,136 | INFO     | will abort job monitoring soon since job state=finished (job is still in queue)
2022-07-04 18:41:13,716 | INFO     | monitor loop #110: job 0:5515971838 is in state 'finished'
2022-07-04 18:41:13,716 | INFO     | will abort job monitoring soon since job state=finished (job is still in queue)
2022-07-04 18:42:15,298 | INFO     | monitor loop #111: job 0:5515971838 is in state 'finished'
2022-07-04 18:42:15,298 | INFO     | will abort job monitoring soon since job state=finished (job is still in queue)
2022-07-04 18:42:50,074 | INFO     | finished stage-out for finished payload, adding job to finished_jobs queue
2022-07-04 18:42:52,785 | INFO     | job 5515971838 has state=finished

I checked some others' tasks and they look ok with a runtime of around one hour or less.

Did you change the system time or something like that? This could have confused the software into hanging until the time "caught up" with the previous time:

I did not touched the system accept monitoring the Consoles F2. (5 running tasks at that moment)
After seen the message "Preparing HITS file" for over an hour, I tried to rivive the mentioned first result.

Before I took a copy of stderr.txt. All three last lines like:
2022-07-04 18:40:13 (5868): Guest Log: ATHENA_PROC_NUMBER=4
2022-07-04 18:40:14 (5868): Guest Log: *** Starting ATLAS job. (PandaID=5515971838 taskID=NULL&cor) ***
2022-07-04 18:41:47 (5868): Guest Log: VBoxService 5.2.32 r132073 (verbosity: 0) linux.amd64 (Jul 12 2019 10:32:28) release log
2022-07-04 18:41:47 (5868): Guest Log: 00:00:00.000104 main Log opened 2022-07-04T18:41:45.667110000Z
2022-07-04 18:41:47 (5868): Guest Log: 00:00:00.000164 main OS Product: Linux
2022-07-04 18:41:47 (5868): Guest Log: 00:00:00.000188 main OS Release: 3.10.0-957.27.2.el7.x86_64
2022-07-04 18:41:47 (5868): Guest Log: 00:00:00.000204 main OS Version: #1 SMP Mon Jul 29 17:46:05 UTC 2019
2022-07-04 18:41:47 (5868): Guest Log: 00:00:00.000222 main Executable: /opt/VBoxGuestAdditions-5.2.32/sbin/VBoxService
2022-07-04 18:41:47 (5868): Guest Log: 00:00:00.000223 main Process ID: 8530
2022-07-04 18:41:47 (5868): Guest Log: 00:00:00.000223 main Package type: LINUX_64BITS_GENERIC
2022-07-04 18:41:47 (5868): Guest Log: 00:00:00.000797 main 5.2.32 r132073 started. Verbose level = 0
2022-07-04 18:41:57 (5868): Guest Log: 00:00:10.002218 timesync vgsvcTimeSyncWorker: Radical guest time change: -7 188 620 002 000ns (GuestNow=1 656 952 917 049 102 000 ns GuestLast=1 656 960 105 669 104 000 ns fSetTimeLastLoop=true )

Normally followed by *** Job finished ***.
About 2 hours difference.
My Local time and the VM-time (UTC) differs 2 hours !!??

After a Reset, 4 Tasks are downloading and .vdi (1,09 GByte).
.vdi download stuck at 84,17% (0.92 from 1.09) Speed 3005.37 KBps.
After retry finished.
Three tasks running now. Taking a look tomorrow.

First three Tasks successful, the next one:
Verschoben:VM environment needs to be cleaned up.

2022-07-04 23:23:45 (13952): Guest Log: 00:00:00.002313 main 5.2.32 r132073 started. Verbose level = 0
2022-07-04 23:23:55 (13952): Guest Log: 00:00:10.012626 timesync vgsvcTimeSyncWorker: Radical guest time change: -7 189 313 248 000ns (GuestNow=1 656 969 834 861 988 000 ns GuestLast=1 656 977 024 175 236 000 ns fSetTimeLastLoop=true )
2022-07-04 23:24:08 (13952): Guest Log: CVMFS is ok
Seeing this after start of inside VM of the Windows-Task.
Don't know, if this can be a sign.

I run 125 tasks so far using mainly two hosts (number 1 & 2 on the list below). No problems of any kind. "HITS file was successfully produced" every time.
Tested configurations (tasks running parallel and cores per task) 1 x 1 core, 2 x 1 core, 2 x 2 cores, 3 x 2 cores ... depending on the RAM available.
I didn't have any other kind of tasks running at the same time.

Host 1 : Boinc 7.20.1 , VirtualBox 6.1.34 , Windows 11 , Intel Xeon X5660 overclocked to 3.8 GHz , 16 GB RAM
Host 2 : Boinc 7.20.1 , VirtualBox 6.1.34 , Windows 10 , Intel Xeon X5650 overclocked to 3.9 GHz , 12 GB RAM
Host 3 : Boinc 7.20.1 , VirtualBox 6.1.34 , Windows 10 , Intel Xeon X5660 overclocked to 3.8 GHz , 48 GB RAM
Host 3 : Boinc 7.20.1 , VirtualBox 6.1.34 , Windows 7 , Intel Core 2 Quad Q9550 overclocked to 3.5 GHz , 8 GB RAM

Alles funkzionieren magnifico with this ATLAS edizione v1.13 und that software combination even though those chips are molto vecchio already (launched in 2010 / 2008).

I'll continue now by running this v1.13 parallel to v2.00 (LHC@home) on hosts 1 & 2 to look for signs of weird behaviour.
1 x 2 cores + 1 x 2 cores ... and ... 1 x 1 cores + 1 x 1 cores
* The first v1.13 tasks running parallel to v2.00 on both hosts completed, der Ausgang ist gut.

Alles funkzionieren magnifico with this ATLAS edizione v1.13 und that software combination even though those chips are molto vecchio already (launched in 2010 / 2008).

Are you Salvatore of Monserrat (from "The name of the Rose")?? :-P

boboviz,
Please, only facts. This is -dev!

boboviz,
Please, only facts. This is -dev!

Ok, ok, calm down
My Atlas wus are all ok and this is a fact!

When Vbox Guest Extensions are active a timesync with the host's RTC happens every 10 seconds.
It's a Vbox function and must not be switched off.

2022-07-04 18:41:47 (5868): Guest Log: 00:00:00.000797 main 5.2.32 r132073 started. Verbose level = 0
2022-07-04 18:41:57 (5868): Guest Log: 00:00:10.002218 timesync vgsvcTimeSyncWorker: Radical guest time change: -7 188 620 002 000ns (GuestNow=1 656 952 917 049 102 000 ns GuestLast=1 656 960 105 669 104 000 ns fSetTimeLastLoop=true )

I wouldn't be afraid of a guest time change if it is a multiple of 3600 seconds since this just shows the VM adjusts the timezone.
What makes me wonder is the small deviation of ~11 seconds in the example above (change: -7 188...).
This may cause a fight between the NTP service inside the VM and the Vbox timesync since the VM can't set the host's RTC.

Thus, the host should always be in sync with an NTP time source.


In addition the host's RTC should be set to UTC. This is the default on Linux and (as far as I know) on Apple.

Windows uses local time but can be configured to use UTC.
Open a powershell with administrator rights and run:

reg add "HKEY_LOCAL_MACHINE\System\CurrentControlSet\Control\TimeZoneInformation" /v RealTimeIsUniversal /d 1 /t REG_DWORD /f

Reboot and check/adjust the BIOS time to the correct UTC value.



@Richie_unstable
@boboviz
Thanks for your comments

[quote]Windows uses local time but can be configured to use UTC.
Open a powershell with administrator rights and run:

reg add "HKEY_LOCAL_MACHINE\System\CurrentControlSet\Control\TimeZoneInformation" /v RealTimeIsUniversal /d 1 /t REG_DWORD /f

Reboot and check/adjust the BIOS time to the correct UTC value./quote]
This is shown during some Tasks - doing nothing from my side!

[quote]Windows uses local time but can be configured to use UTC.
Open a powershell with administrator rights and run:

reg add "HKEY_LOCAL_MACHINE\System\CurrentControlSet\Control\TimeZoneInformation" /v RealTimeIsUniversal /d 1 /t REG_DWORD /f

Reboot and check/adjust the BIOS time to the correct UTC value./quote]

This is shown during some Tasks - doing nothing from my side!
2022-07-04 23:23:45 (9592): Guest Log: VBoxService 5.2.32 r132073 (verbosity: 0) linux.amd64 (Jul 12 2019 10:32:28) release log
2022-07-04 23:23:45 (9592): Guest Log: 00:00:00.000345 main Log opened 2022-07-04T23:23:44.220636000Z
2022-07-04 23:23:45 (9592): Guest Log: 00:00:00.000458 main OS Product: Linux
2022-07-04 23:23:45 (9592): Guest Log: 00:00:00.000480 main OS Release: 3.10.0-957.27.2.el7.x86_64
2022-07-04 23:23:45 (9592): Guest Log: 00:00:00.000500 main OS Version: #1 SMP Mon Jul 29 17:46:05 UTC 2019
2022-07-04 23:23:45 (9592): Guest Log: 00:00:00.000518 main Executable: /opt/VBoxGuestAdditions-5.2.32/sbin/VBoxService

Restart of Boinc, vboxwrapper for production AND -dev 204.
Four Atlas from -dev (last night postponed) are restarted.

In addition the host's RTC should be set to UTC. This is the default on Linux and (as far as I know) on Apple.

It's not the default for Windows.
I adjusted my registry and the BIOS-clock to use UTC.
At least the timesync in Guest Log is gone now.
I'm trying to introduce maeax's postponed task problems and are running LHC@home Theory together with dev-ATLAS on my laptop. No problem so far.
Testing this I noted that ATLAS VM is showing UTC-time as it did before my registry change and Theory is using local time as it did before.

VBoxService 5.2.32 r132073

VBoxGuestAdditions-5.2.32
This is the client part of VBoxGuestAdditions running inside the ATLAS VM.
It is included in the ATLAS vdi file.
The functions we need (shared folders) didn't change in more recent versions, hence 5.2.32 is OK.

Nonetheless, if you install the host part of the VBoxGuestAdditions they should always match the main Vbox version.

Vboxwrapper since v26204 forwards the host's RTC setting to the guest.
It assumes UTC on Linux/Apple hosts and reads the registry setting on Windows hosts.

The VMs display (and log) the time according to the timezone setting of the running VM-user.

More important would be to sync the time with NTP as this avoids jumps.

Restart of Boinc, vboxwrapper for production AND -dev 204.
Four Atlas from -dev (last night postponed) are restarted.

Seeing ATLAS_vbox_1.13_image.vdi for this 4 -dev Tasks only as entry in Manager.
Have downloaded 30 Tasks in Production and stopped testing in -dev, so long.

If Virtualbox 6.0.14 is a Problem (Version from Boinc-Website),
testing with 6.1.34 next.

I'm trying to introduce maeax's postponed task problems and are running LHC@home Theory together with dev-ATLAS on my laptop.

Postponed issue reproduced.

I have one Theory running from LHC@home (production server) and 1 ATLAS from dev and 7 dev-ATLAS-tasks in queue ready to start.
After the running ATLAS-task finished all queued tasks start for ~40 seconds and get postponed. When you try a BOINC restart these tasks don't have a boot medium.

lhcathome-dev 05 Jul 12:36:30 Computation for task djbKDmmucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmOIHKDmV3NHZm_0 finished
lhcathome-dev 05 Jul 12:36:31 Starting task fNKMDmvucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmWIHKDm6BKY3m_0
lhcathome-dev 05 Jul 12:36:34 Started upload of djbKDmmucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmOIHKDmV3NHZm_0_r769731847_ATLAS_result
lhcathome-dev 05 Jul 12:36:34 Started upload of djbKDmmucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmOIHKDmV3NHZm_0_r769731847_ATLAS_hits
lhcathome-dev 05 Jul 12:36:46 Finished upload of djbKDmmucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmOIHKDmV3NHZm_0_r769731847_ATLAS_hits
lhcathome-dev 05 Jul 12:37:09 Finished upload of djbKDmmucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmOIHKDmV3NHZm_0_r769731847_ATLAS_result
lhcathome-dev 05 Jul 12:37:13 Sending scheduler request: To report completed tasks.
lhcathome-dev 05 Jul 12:37:13 Reporting 1 completed tasks
lhcathome-dev 05 Jul 12:37:13 Not requesting tasks: "no new tasks" requested via Manager
lhcathome-dev 05 Jul 12:37:14 Scheduler request completed
lhcathome-dev 05 Jul 12:37:14 Project requested delay of 61 seconds
lhcathome-dev 05 Jul 12:37:16 Task fNKMDmvucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmWIHKDm6BKY3m_0 postponed for 86400 seconds: VM environment needs to be cleaned up.
lhcathome-dev 05 Jul 12:37:16 Starting task 3dPMDmuucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmVIHKDmKasUfm_0
lhcathome-dev 05 Jul 12:38:02 Task 3dPMDmuucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmVIHKDmKasUfm_0 postponed for 86400 seconds: VM environment needs to be cleaned up.
lhcathome-dev 05 Jul 12:38:02 Starting task QILMDmtucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmUIHKDmbODRwm_0
lhcathome-dev 05 Jul 12:38:47 Task QILMDmtucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmUIHKDmbODRwm_0 postponed for 86400 seconds: VM environment needs to be cleaned up.
lhcathome-dev 05 Jul 12:38:48 Starting task NFCLDmiucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmKIHKDmnUTkDo_0
lhcathome-dev 05 Jul 12:39:33 Task NFCLDmiucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmKIHKDmnUTkDo_0 postponed for 86400 seconds: VM environment needs to be cleaned up.
lhcathome-dev 05 Jul 12:39:33 Starting task n5pMDmrucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmTIHKDmhLE0Gm_0
lhcathome-dev 05 Jul 12:40:18 Task n5pMDmrucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmTIHKDmhLE0Gm_0 postponed for 86400 seconds: VM environment needs to be cleaned up.
lhcathome-dev 05 Jul 12:40:18 Starting task A9kKDmjucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmLIHKDmcwiPhm_0
lhcathome-dev 05 Jul 12:41:03 Task A9kKDmjucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmLIHKDmcwiPhm_0 postponed for 86400 seconds: VM environment needs to be cleaned up.
lhcathome-dev 05 Jul 12:41:04 Starting task exKLDmoucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmQIHKDmOBKfUm_0
lhcathome-dev 05 Jul 12:41:48 Task exKLDmoucS1n7Olcko1bjSoqABFKDmABFKDmKFbSDmQIHKDmOBKfUm_0 postponed for 86400 seconds: VM environment needs to be cleaned up.
LHC@home 05 Jul 12:48:08 Computation for task Theory_2390-1098582-268_0 finished

I let them crash by using an atlas done file. See the error results: https://lhcathomedev.cern.ch/lhcathome-dev/results.php?hostid=4600&offset=0&show_names=0&state=6&appid=5

So there seems to be a real issue when mixing the new multi attach vboxwrapper with the older LHC@home tasks.

Edit: I reproduced it on my other PC too: https://lhcathomedev.cern.ch/lhcathome-dev/result.php?resultid=3097580