View Issue Details

IDProjectCategoryView StatusLast Update
0000375LDMud 3.3Runtimepublic2018-01-29 22:57
ReporterlarsAssigned ToGnomi  
PrioritynormalSeverityminorReproducibilityalways
Status resolvedResolutionfixed 
Target Version3.3.719Fixed in Version3.3.719 
Summary0000375: call_out() timing is incorrect
DescriptionAssuming an alarm interval of 2: a call_out("fun", 2) done from inside a heartbeat will have fun() executed inside the current backend cycle, and not the next.

This behaviour is caused by the fact that the call_out timing is based on relative delays, instead of being tied directly to the current time. On the other hand, some old code exploits this behaviour to have functions execute after the current player commands, but before the next.
Additional InformationThe basic problem can be solved by storing absolute execution times into the call_out list; but I don't see any way to preserve the old code behavior in this.
TagsNo tags attached.

Activities

peng

2005-03-19 13:01

reporter   ~0000357

Iirc we use call_out("fun",0) to achieve the goal of putting the call_out behind the current commands and just before the next ones. Main reason for this is resetting evals for some expensive operations. But I may wrong here.

zesstra

2009-03-04 16:39

administrator   ~0000973

call_out chains for preventing 'too long eval' is standard behaviour, yes.

I suggest, if we change the timing behaviour, we should do it in 3.5.x.
Any opinions, if we want to change it or declare it a feature...?

Gnomi

2009-03-04 17:14

manager   ~0000976

I think the timing problem should be fixed in 3.5 (I wouldn't mind if we do it in 3.3). I don't see any problem with old code behavior: If you wan't the old behaviour you use call_out("fun",0).

As for too long eval errors: When calling from a heart_beat you don't want the old behavior (heart_beat and call_outs from the same object share their eval count in each cycle).

zesstra

2009-03-04 17:52

administrator   ~0000979

I thought to not force wizards to check and change their code between e.g. 3.3.719 and 3.3.720. Probably the code Lars described is rather rare. But I guess, very difficult to find. But I could ultimately also live with fixing it in 3.3.

You are right concerning the eval costs. I meant call_out chains in general, not with a specific delay of 2 or 0, which are not a good idea, right. When we migrated from our old LP driver to LDMud 3.3 we had about 2-3 dozens call_out(...,0) in a call_out, which resulted in a callout chain with zero delay, was quite funny. ;-)

Gnomi

2009-05-20 17:31

manager   ~0001125

Last edited: 2009-05-21 06:58

I don't think, wizards have to check their code. If someone wanted that behavior of starting a call_out directly after a heart_beat he would have called call_out("fun", 0). If there's somewhere a call_out("fun", 2) from a heart_beat it almost never was meant to start directly after the heart_beat but 2 seconds later. That's why I don't think this bugfix would break code.

2009-05-26 14:17

 

bug375.diff (5,020 bytes)   
Index: trunk/test/t-0000375.c
===================================================================
--- trunk/test/t-0000375.c	(Revision 0)
+++ trunk/test/t-0000375.c	(Revision 0)
@@ -0,0 +1,78 @@
+#include "/inc/base.inc"
+
+/* These functions are for the clone (the player object). */
+void start_client()
+{
+    net_connect("127.0.0.1", query_mud_port());
+    set_heart_beat(1);
+}
+
+int logon(int flag)
+{
+    enable_telnet(0);
+    set_prompt("");
+
+    return 1;
+}
+
+object connect()
+{
+   enable_telnet(0);
+   set_prompt("");
+
+   return clone_object(this_object());
+}
+
+void fun(int* oldtime)
+{
+    int* now = utime();
+
+    remove_call_out(#'shutdown);
+
+    // Is there a time difference of
+    // at least 0.5 seconds?
+    if (oldtime[1] < 500000)
+        oldtime[1] += 500000;
+    else
+    {
+        oldtime[1] -= 500000;
+        oldtime[0] += 1;
+    }
+
+    if ((oldtime[0] == now[0])
+       ?(oldtime[1] < now[1])
+       :(oldtime[0] < now[0]))
+        shutdown(0);
+    else
+        shutdown(1);
+}
+
+void heart_beat()
+{
+    call_out("fun", __ALARM_TIME__, utime());
+}
+
+void run_test()
+{
+    int result;
+
+    msg("\nRunning test for #0000375:\n"
+        "--------------------------\n");
+
+    call_out("run_test2", 0);
+}
+
+void run_test2()
+{
+    object dummy;
+    dummy = clone_object(this_object());
+    dummy->start_client();
+
+    call_out(#'shutdown, (__HEART_BEAT_INTERVAL__+__ALARM_TIME__)*2, 1); // Just to make sure.
+}
+
+string *epilog(int eflag)
+{
+    run_test();
+    return 0;
+}
Index: trunk/src/call_out.c
===================================================================
--- trunk/src/call_out.c	(Revision 2592)
+++ trunk/src/call_out.c	(Arbeitskopie)
@@ -216,28 +216,19 @@
     return sp;
 } /* v_call_out() */
 
+
 /*-------------------------------------------------------------------------*/
 void
-call_out (void)
+next_call_out_cycle (void)
 
-/* Check if there is any callout due to be called. If yes, do so.
- * This function is called from the heart_beat handling in the backend.c.
- * It sets up its own error recovery context so that errors during an
- * execution won't disturb the rest of the game.
+/* Starts the next call_out cycle by decrementing the first delta.
+ * This function is called in the backend cycle before heart_beats are handled.
  */
 
 {
     static int last_time;
       /* Last time this function was called */
 
-    static struct call *current_call_out;
-      /* Current callout, static so that longjmp() won't clobber it. */
-
-    static object_t *called_object;
-      /* Object last called, static so that longjmp() won't clobber it */
-
-    struct error_recovery_info error_recovery_info;
-
     /* No calls pending: just update the last_time and return */
 
     if (call_list == NULL)
@@ -250,12 +241,38 @@
     if (last_time == 0)
         last_time = current_time;
 
-    /* Update the first .delta in the list (so it won't happen
-     * twice in case of an error.
+    /* Update the first .delta in the list.
      */
     call_list->delta -= current_time - last_time;
 
     last_time = current_time;
+} /* next_call_out_cycle() */
+
+
+/*-------------------------------------------------------------------------*/
+void
+call_out (void)
+
+/* Check if there is any callout due to be called. If yes, do so.
+ * This function is called from the heart_beat handling in the backend.c.
+ * It sets up its own error recovery context so that errors during an
+ * execution won't disturb the rest of the game.
+ */
+
+{
+    static struct call *current_call_out;
+      /* Current callout, static so that longjmp() won't clobber it. */
+
+    static object_t *called_object;
+      /* Object last called, static so that longjmp() won't clobber it */
+
+    struct error_recovery_info error_recovery_info;
+
+    /* No calls pending: fine. */
+
+    if (call_list == NULL)
+        return;
+
     current_interactive = NULL;
 
     /* Activate the local error recovery context */
Index: trunk/src/call_out.h
===================================================================
--- trunk/src/call_out.h	(Revision 2592)
+++ trunk/src/call_out.h	(Arbeitskopie)
@@ -8,6 +8,7 @@
 /* --- Prototypes --- */
 
 extern void  call_out(void);
+extern void  next_call_out_cycle(void);
 extern size_t  call_out_status(strbuf_t *sbuf, Bool verbose);
 extern void  callout_dinfo_status(svalue_t *svp, int value);
 extern void  remove_stale_call_outs(void);
Index: trunk/src/backend.c
===================================================================
--- trunk/src/backend.c	(Revision 2592)
+++ trunk/src/backend.c	(Arbeitskopie)
@@ -717,6 +717,11 @@
             time_to_call_heart_beat = MY_FALSE;
             alarm(alarm_time);
 
+            /* So call_outs from heart_beats are
+             * correctly timed.
+             */
+            next_call_out_cycle();
+
             /* Do the timed events */
 	    if (!synch_heart_beats
              || time_of_last_hb + heart_beat_interval <= current_time)
bug375.diff (5,020 bytes)   

Gnomi

2009-05-26 14:19

manager   ~0001164

I uploaded a patch that fixes this by starting the call_out cycle before heart_beats are handled (call_outs are not executed, but the first delay is decremented and last_time is updated, so it does correctly reflect the timing during the heart_beats).

zesstra

2009-05-26 17:28

administrator   ~0001166

Looks good to me, I did not expect it to be that simple. :-)

Gnomi

2009-05-27 14:24

manager   ~0001169

Committed as r2596.

Issue History

Date Modified Username Field Change
2005-03-17 23:42 lars New Issue
2005-03-19 13:01 peng Note Added: 0000357
2009-03-04 16:39 zesstra Note Added: 0000973
2009-03-04 16:39 zesstra Status new => confirmed
2009-03-04 16:39 zesstra Project LDMud => LDMud 3.5
2009-03-04 17:14 Gnomi Note Added: 0000976
2009-03-04 17:52 zesstra Note Added: 0000979
2009-05-20 17:31 Gnomi Note Added: 0001125
2009-05-20 17:31 Gnomi Assigned To => Gnomi
2009-05-20 17:31 Gnomi Product Version 3.3 =>
2009-05-21 06:58 Gnomi Note Edited: 0001125
2009-05-26 14:17 Gnomi File Added: bug375.diff
2009-05-26 14:19 Gnomi Note Added: 0001164
2009-05-26 14:20 Gnomi Project LDMud 3.5 => LDMud 3.3
2009-05-26 14:20 Gnomi Target Version => 3.3.719
2009-05-26 17:28 zesstra Note Added: 0001166
2009-05-27 14:24 Gnomi Note Added: 0001169
2009-05-27 14:24 Gnomi Status confirmed => resolved
2009-05-27 14:24 Gnomi Fixed in Version => 3.3.719
2009-05-27 14:24 Gnomi Resolution open => fixed
2010-11-16 10:42 Gnomi Source_changeset_attached => ldmud.git master a1e7d333
2018-01-29 19:59 Gnomi Source_changeset_attached => ldmud.git master a1e7d333
2018-01-29 22:57 Gnomi Source_changeset_attached => ldmud.git master a1e7d333