1.11.153721 - ScriptCallQueue.CallLater on server stops calling function at correct interval after ~4.5 hours
Assigned, UrgentPublic
Actions

Description

The ScriptCallQueue.CallLater method is useful for calling a function either one time or periodically after a specified amount of time. However, the function stops getting called at the correct delay after a server has been running for around 4.5 hours.

The function passed to ScriptCallQueue.CallLater should be called after the specified delay within an acceptable margin or error (i.e. a second or two), regardless of how long the server has been running.

I originally reported this bug in a comment under T151279 but it looks like that bug hasn't gotten enough attention, as it is still in the "needs more info" state.

This bug is not new in 1.11.153721 experimental. It was also present in previous 1.11.x experimental versions and in 1.10.153598 stable.

Details

Severity: Major
Resolution: Open
Reproducibility: Always
Operating System: Windows 10 x64
Category: General

Steps To Reproduce

The issue can be easily reproduced by running DayZ Server with the following mpmission folder and server config file:

test.chernarusplus.zip1 KBDownload

test.cfg594 BDownload

Unzip the test.chernarusplus.zip file (the folder it contained was located on my P: drive when I ran it) and then run DayZ server using the following command line:

.\DayZServer_x64.exe "-config=test.cfg" "-profiles=testprofile" "-mission=P:\test.chernarusplus"

Let the server run for more than 5 hours. When I ran it, I let the server run for almost 10 hours. Here are the log files from my run:

script_2021-02-12_07-32-43.log31 KBDownload

DayZServer_x64_2021-02-12_07-32-40.RPT21 KBDownload

The mpmission's init.c is implemented to call a periodic function, using ScriptCallQueue.CallLater, every 60 seconds, which prints the current date and time in UTC. The script also prints the date and time when the server starts and stops. As you can see, in the attached script_2021-02-12_07-32-43.log file, the mission class constructor printed the server start date/time at 13:32:57 UTC:

SCRIPT       : CustomMission: 2021-02-12 13:32:57

The script then logged a timestamp every 60 seconds until 18:12:05 UTC, when it slowed down drastically. The next printed timestamp was at 18:53:47, about 40 minutes later. The periodic date/time logs continued to be printed at increasingly larger intervals instead of the expected 60-second intervals:

SCRIPT       : Periodic: 2021-02-12 18:12:05
...
SCRIPT       : Periodic: 2021-02-12 18:53:47
...
SCRIPT       : Periodic: 2021-02-12 20:42:28
...
SCRIPT       : Periodic: 2021-02-12 22:33:12

(I have removed the "Chernarus::Weather" logs in the above excerpt for brevity)

Finally, the log shows the date/time printed when I stopped the server:

SCRIPT       : ~CustomMission: 2021-02-12 23:04:51

Additional Information

From scripts\2_gamelib\tools.c, this is the function that the bug affects:

class ScriptCallQueue
{
        ...
	proto void CallLater(func fn, int delay = 0, bool repeat = false, void param1 = NULL, void param2 = NULL, void param3 = NULL, void param4 = NULL, void param5 = NULL, void param6 = NULL, void param7 = NULL, void param8 = NULL, void param9 = NULL);	
        ...
};

Related Objects

Mentioned Here: T151279: Server performance / Scripting performance loss after ~5 hours of runtime

Event Timeline

tjensen created this task.Feb 13 2021, 12:50 AM

Do servers even stay up for that long??

Geez changed the task status from New to Assigned.Feb 15 2021, 12:51 PM

That can explain some weird bugs I encounter.

The bug does not affect Timer.
I'm switching all my CallLaters to Timers until the bug will be fixed.

GlutenFreeVapes added a subscriber: GlutenFreeVapes.Mar 17 2021, 1:38 PM

Hoping this is fixed soon!

daemonforge added a subscriber: daemonforge.Jun 24 2021, 4:31 AM

@Geez 2022

mrdarn added a subscriber: mrdarn.Jul 14 2022, 9:16 AM

Spaggie added a subscriber: Spaggie.Jul 14 2022, 9:18 AM

lava76 added a subscriber: lava76.Sep 15 2022, 5:28 PM

NATION added a subscriber: NATION.Sep 20 2022, 12:24 AM

Hunterz added a subscriber: Hunterz.Nov 11 2022, 2:35 PM

Perivision added a subscriber: Perivision.Nov 21 2022, 1:06 PM

This issue seems to now be affecting the Namalsk 3D Printer, and the DeerIsle KMUC door.

Same issues. After 3-5 hours, the result of the CallLater never seems to fire.

Issue reported in the Namalsk discord too.

Seeing more and more frustrated players on Deer Isle (vault door) and Namalsk (printer) servers, we've put up warning messages for them to only attempt missions in the 3 hours after a restart (as 4 hour server restarts are too many I feel). Engine bug

In T151279#2143641, @tjensen wrote:

Is the GetTime() value stored internally as a 32-bit float? That could explain the issue, since 32-bit floats have only 24 bits of mantissa and therefore integer values above 16777216 can lose precision when converted to 32-bit floats.

Please fix, dayz servers should run weeks without restarts.

Hi, friends! I see that this bug has gathered quite a bit of attention lately, due to it affecting Deer Isle vault doors and the suit printer on Namalsk.

Just wanted to remind everyone that if you switch your mods to use the Timer class, instead, you won't have this problem. It doesn't take that much work to switch and you'll be much happier in the end.

💖 you bye

I'm hearing that John, Deer Isle is unmotivated to do this, so that might not be an option

Namalsk is Adam and I think he would know

Thanks for the workaround but that requires them to make changes rather than fixing an Engine Bug (which would be the Enfusion Team)

Timer and CallLater have pros and cons. Switching to Timer is just workaround. Personally preferring fix already very good described issue.

bantamgreg added a subscriber: bantamgreg.Dec 1 2022, 9:20 AM

In T156746#2385202, @Hunterz wrote:

Timer and CallLater have pros and cons. Switching to Timer is just workaround. Personally preferring fix already very good described issue.

I'm currently facing the same problem. Could you maybe elaborate on what you think the Timer's cons are?

I tried the Timer class in the past to replace callLater but it is a lot lot more ressource consumming.

Other than the Timer and CallLater, is there another way to do this? or is a fix from Enfusion for the CallLater issue the best resolution for this?

I'm pretty sure that vanilla functions use calllater as well, so the best fix you can apply is to use a modified version of the game executable, similar how cheaters edit things in games and try to fix the issue yourself or rewrite all the functions including vanilla which have calllater in them.

1.11.153721 - ScriptCallQueue.CallLater on server stops calling function at correct interval after ~4.5 hoursAssigned, UrgentPublicActions

Description

Details

Related Objects

Event Timeline

1.11.153721 - ScriptCallQueue.CallLater on server stops calling function at correct interval after ~4.5 hours
Assigned, UrgentPublic
Actions