fix: refine scheduler timing and lateness warnings

 - Treat Event.scheduled as the nominal start time and compute the next
   nominal fire time via scheduled_next = scheduled + interval, keeping
   a fixed-rate schedule grid without accumulating jitter.

 - Rework QueueEvent() to requeue at scheduled_next when the job
   finishes on time or early, and to shift the nextqueue to now+10ms
   only when the nominal time was already missed (same as before, but
   using Debug instead of a Warning message)

 - Measure lateness at dispatch time in SchedThread() and emit a
   Warning only when the start delay exceeds a 100 ms tolerance.  This
   message replaces the previous generic (and often repeated) “last
   execution overlaps with scheduled execution” warning.

 - Add optional (commented-out) diagnostic logging in QueueEvent() and
   SchedThread() to trace nominal schedule times, actual wakeups, and
   cond wait results when investigating scheduler behavior. It turns
   out that at least under macOS, the actual timer granularity of
   pthread_cond_timedwait() is quite bad (overshooting often 3-5 ms)

Author: gustafn

nsd/sched.c

@@ -325,9 +325,7 @@ Ns_ScheduleProcEx(Ns_SchedProc *proc, void *clientData, unsigned int flags,
     } else {
         Event    *ePtr;
         int       isNew;
-        Ns_Time   now;
 
-        Ns_GetTime(&now);
         ePtr = ns_malloc(sizeof(Event));
         ePtr->flags = flags;
         ePtr->nextqueue.sec = 0;
@@ -344,6 +342,8 @@ Ns_ScheduleProcEx(Ns_SchedProc *proc, void *clientData, unsigned int flags,
             id = (int)NS_ERROR;
             ns_free(ePtr);
         } else {
+            Ns_Time now;
+
             do {
                 static int nextId = 0;
 
@@ -354,6 +354,7 @@ Ns_ScheduleProcEx(Ns_SchedProc *proc, void *clientData, unsigned int flags,
                 ePtr->hPtr = Tcl_CreateHashEntry(&eventsTable, INT2PTR(id), &isNew);
             } while (isNew == 0);
             Tcl_SetHashValue(ePtr->hPtr, ePtr);
+            Ns_GetTime(&now);
             ePtr->id = id;
             ePtr->scheduled = now;
             QueueEvent(ePtr);
@@ -683,32 +684,64 @@ QueueEvent(Event *ePtr)
             }
             ePtr->scheduled = ePtr->nextqueue;
         } else {
-            Ns_Time diff, now;
+            Ns_Time scheduled_next, now;
+            long    cmp;
 
-            ePtr->nextqueue = ePtr->scheduled;
-            Ns_IncrTime(&ePtr->nextqueue, ePtr->interval.sec, ePtr->interval.usec);
             /*
-             * The update time is the next scheduled time.
+             * "scheduled"      : desired time for this run.
+             * "scheduled_next" : desired time for the next run.
              */
-            ePtr->scheduled = ePtr->nextqueue;
+            scheduled_next = ePtr->scheduled;
+
+            /* Compute planed next run: scheduled + interval */
+            ePtr->nextqueue = ePtr->scheduled;
+            Ns_IncrTime(&scheduled_next, ePtr->interval.sec, ePtr->interval.usec);
 
+            /*
+             * If the job finished before its next nominal start, queue
+             * exactly at scheduled_next. Otherwise we’d overlap: push the
+             * next run to now + 10ms.
+             */
             Ns_GetTime(&now);
-            d = Ns_DiffTime(&ePtr->nextqueue, &now, &diff);
-            Ns_Log(Debug, "sched: compute next run time based on: scheduled " NS_TIME_FMT
-                   " diff %ld",
-                   (int64_t)ePtr->scheduled.sec, ePtr->scheduled.usec, d);
 
-            if (d == -1) {
+            cmp = Ns_DiffTime(&scheduled_next, &now, NULL);
+
+            if (cmp == 1 || cmp == 0) {
+                /*
+                 * scheduled_next >= now: we are on time or early
+                 */
+                ePtr->nextqueue = scheduled_next;
+            } else {
                 /*
-                 * The last execution took longer than the schedule
-                 * interval. Re-schedule after 10ms.
+                 * scheduled_next < now: we already missed the nominal time
                  */
                 ePtr->nextqueue = now;
                 Ns_IncrTime(&ePtr->nextqueue, 0, 10000);
-                Ns_Log(Warning, "sched id %d: last execution overlaps with scheduled execution; "
-                       "running late", ePtr->id);
+                Ns_Log(Debug, "job %d: we missed nominal time", ePtr->id);
             }
+            /*Ns_Log(Notice,
+                   "QueueEvent id %d: now " NS_TIME_FMT " scheduled " NS_TIME_FMT " nextqueue " NS_TIME_FMT,
+                   ePtr->id,
+                   (int64_t)now.sec, now.usec,
+                   (int64_t)ePtr->scheduled.sec, ePtr->scheduled.usec,
+                   (int64_t)ePtr->nextqueue.sec, ePtr->nextqueue.usec);*/
+
+            /* store the nominal time for the NEXT run */
+            ePtr->scheduled = scheduled_next;
         }
+#if 0
+        ns_pause 0
+        ns_schedule_proc 1s {ns_log notice ping}
+        ns_schedule_proc 1s {ns_sleep 2s}
+
+        ns_schedule_proc 1s {ns_log notice ping}
+        ns_schedule_proc 3s {ns_sleep 5s}
+
+        ns_schedule_proc 100ms {ns_sleep 50ms}
+
+        ns_schedule_proc 1s {ns_sleep 2s}
+        ns_schedule_proc -thread 1s {ns_sleep 2s}
+#endif
 
         ePtr->qid = ++nqueue;
         /*
@@ -972,16 +1005,36 @@ SchedThread(void *UNUSED(arg))
          * For events ready to run, either create a thread for
          * detached events or add to a list of synchronous events.
          */
-
         Ns_GetTime(&now);
         while (nqueue > 0 && Ns_DiffTime(&queue[1]->nextqueue, &now, NULL) <= 0) {
+            Ns_Time late, tolerate = {0, 100000};  /* 100 ms */
+
             ePtr = DeQueueEvent(1);
 
 #ifdef NS_SCHED_TRACE_EVENTS
             Ns_Log(Notice, "... dequeue event (id %d) " NS_TIME_FMT,
                    ePtr->id,
                    (int64_t)ePtr->nextqueue.sec, ePtr->nextqueue.usec);
 #endif
+            /*
+             * Measure how late we are for THIS execution
+             */
+            if (Ns_DiffTime(&now, &ePtr->scheduled, &late) == 1) {    /* now > scheduled */
+                /*Ns_Log(Notice,
+                       "at "NS_TIME_FMT ": sched id %d: job started late by %ld.%06ld sec (interval %ld.%06ld sec)",
+                       (long long)now.sec, (long)now.usec,
+                       ePtr->id,
+                       (long)late.sec, (long)late.usec,
+                       (long)ePtr->interval.sec, (long)ePtr->interval.usec);*/
+
+                if (Ns_DiffTime(&late, &tolerate, NULL) == 1) {            /* late > tolerate */
+                    Ns_Log(Warning,
+                           "sched id %d: job started late by %ld.%06ld sec (interval %ld.%06ld sec)",
+                           ePtr->id,
+                           (long)late.sec, (long)late.usec,
+                           (long)ePtr->interval.sec, (long)ePtr->interval.usec);
+                }
+            }
             if ((ePtr->flags & NS_SCHED_ONCE) != 0u) {
                 Tcl_DeleteHashEntry(ePtr->hPtr);
                 ePtr->hPtr = NULL;
@@ -1057,17 +1110,26 @@ SchedThread(void *UNUSED(arg))
                 QueueEvent(ePtr);
             }
         }
-
         /*
          * Wait for the next ready event.
          */
         if (nqueue == 0) {
             Ns_CondWait(&schedcond, &lock);
         } else if (!shutdownPending) {
+            Ns_ReturnCode status;
+
             timeout = queue[1]->nextqueue;
-            (void) Ns_CondTimedWait(&schedcond, &lock, &timeout);
+            /*Ns_Log(Notice, "after job next queue timeout " NS_TIME_FMT,
+                     (int64_t)timeout.sec, timeout.usec);*/
+            status = Ns_CondTimedWait(&schedcond, &lock, &timeout);
+            (void)status;
+            /*{
+                Ns_Time now;
+                Ns_GetTime(&now);
+                Ns_Log(Notice, "at " NS_TIME_FMT ": CondTimedWait returned %s",
+                       (int64_t)now.sec, now.usec, Ns_ReturnCodeString(status));
+                       }*/
         }
-
     }
 
     /*