Skip to content

Commit c89e451

Browse files
committed
fix(sched): reduce false "job started late" warnings and improve log message
- Added DStringAppendSchedFlags() helper to render NS_SCHED_* flags into a human-readable "FLAG1|FLAG2" string for logging. - In SchedThread(), normalize events whose first nextqueue time is already in the past at scheduler start by resetting scheduled/nextqueue/lastqueue to "now" to avoid spurious "job started late" messages after long startup. Effectively, the minimal start time is the time, when the sched thread is started. - Added decoded scheduler flags to the late-start warning to improving diagnosability. - Cosmetics: Register ProcInfo for CloseWaitingCheckExpire()
1 parent 626acde commit c89e451

File tree

3 files changed

+78
-2
lines changed

3 files changed

+78
-2
lines changed

nsd/sched.c

Lines changed: 72 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -973,6 +973,54 @@ FreeEvent(Event *ePtr)
973973
ns_free(ePtr);
974974
}
975975

976+
/*
977+
*----------------------------------------------------------------------
978+
*
979+
* NsDStringAppendSchedFlags --
980+
*
981+
* Decode a scheduled flags bitmask into a human‐readable string
982+
* of flag names separated by '|' and append it to a Tcl_DString.
983+
*
984+
* Returns:
985+
* A pointer to the internal string buffer of dsPtr, containing the
986+
* appended flag names.
987+
*
988+
* Side Effects:
989+
* Appends the textual representations of each set flag to the
990+
* Tcl_DString, inserting '|' between multiple flags.
991+
*
992+
*----------------------------------------------------------------------
993+
*/
994+
static char *
995+
DStringAppendSchedFlags(Tcl_DString *dsPtr, unsigned int flags)
996+
{
997+
int count = 0;
998+
size_t i;
999+
static const struct {
1000+
unsigned int state;
1001+
const char *label;
1002+
} options[] = {
1003+
{ NS_SCHED_THREAD, "THREAD" },
1004+
{ NS_SCHED_ONCE, "ONCE" },
1005+
{ NS_SCHED_DAILY, "DAILY" },
1006+
{ NS_SCHED_WEEKLY, "WEEKLY" },
1007+
{ NS_SCHED_PAUSED, "PAUSED" },
1008+
{ NS_SCHED_RUNNING, "RUNNING"},
1009+
};
1010+
1011+
NS_NONNULL_ASSERT(dsPtr != NULL);
1012+
1013+
for (i = 0; i<sizeof(options) / sizeof(options[0]); i++) {
1014+
if ((options[i].state & flags) != 0u) {
1015+
if (count > 0) {
1016+
Tcl_DStringAppend(dsPtr, "|", 1);
1017+
}
1018+
Tcl_DStringAppend(dsPtr, options[i].label, TCL_INDEX_NONE);
1019+
count ++;
1020+
}
1021+
}
1022+
return dsPtr->string;
1023+
}
9761024

9771025
/*
9781026
*----------------------------------------------------------------------
@@ -1003,6 +1051,23 @@ SchedThread(void *UNUSED(arg))
10031051
Ns_Log(Notice, "sched: starting");
10041052

10051053
Ns_MutexLock(&lock);
1054+
1055+
/*
1056+
* For all events whose nextqueue is already in the past (i.e., whose
1057+
* first scheduled time was during long startup), reset their base time to
1058+
* 'now' so they don't appear "late" on the very first run.
1059+
*/
1060+
Ns_GetTime(&now);
1061+
for (int i = 1; i <= nqueue; ++i) {
1062+
Event *e = queue[i];
1063+
1064+
if (Ns_DiffTime(&e->nextqueue, &now, NULL) <= 0) {
1065+
e->scheduled = now;
1066+
e->nextqueue = now;
1067+
e->lastqueue = now; /* optional, but keeps things consistent */
1068+
}
1069+
}
1070+
10061071
while (!shutdownPending) {
10071072

10081073
/*
@@ -1024,6 +1089,7 @@ SchedThread(void *UNUSED(arg))
10241089
* Measure how late we are for THIS execution
10251090
*/
10261091
if (Ns_DiffTime(&now, &ePtr->scheduled, &late) == 1) { /* now > scheduled */
1092+
10271093
/*Ns_Log(Notice,
10281094
"at "NS_TIME_FMT ": sched id %d: job started late by %ld.%06ld sec (interval %ld.%06ld sec)",
10291095
(long long)now.sec, (long)now.usec,
@@ -1032,11 +1098,16 @@ SchedThread(void *UNUSED(arg))
10321098
(long)ePtr->interval.sec, (long)ePtr->interval.usec);*/
10331099

10341100
if (Ns_DiffTime(&late, &tolerate, NULL) == 1) { /* late > tolerate */
1101+
Tcl_DString ds;
1102+
1103+
Tcl_DStringInit(&ds);
10351104
Ns_Log(Warning,
1036-
"sched id %d: job started late by %ld.%06ld sec (interval %ld.%06ld sec)",
1105+
"sched id %d: job started late by %ld.%06ld sec (flags %s, interval %ld.%06ld sec)",
10371106
ePtr->id,
10381107
(long)late.sec, (long)late.usec,
1108+
DStringAppendSchedFlags(&ds, ePtr->flags),
10391109
(long)ePtr->interval.sec, (long)ePtr->interval.usec);
1110+
Tcl_DStringFree(&ds);
10401111
}
10411112
}
10421113
if ((ePtr->flags & NS_SCHED_ONCE) != 0u) {

nsd/tclhttp.c

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2692,6 +2692,8 @@ HttpClientStartJanitor(void)
26922692
0,
26932693
&interval,
26942694
NULL);
2695+
Ns_RegisterProcInfo((ns_funcptr_t)CloseWaitingCheckExpire,
2696+
"httpclient:close-waiting", NULL);
26952697
}
26962698

26972699
/*

nsdb/dbinit.c

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -661,7 +661,6 @@ NsDbInitPools(void)
661661
Tcl_SetHashValue(hPtr, ns_const2voidp(poolPtr));
662662
}
663663
}
664-
Ns_RegisterProcInfo((ns_funcptr_t)CheckPool, "nsdb:check", CheckArgProc);
665664
}
666665

667666

@@ -1457,6 +1456,10 @@ CreatePool(const char *pool, const char *section, const char *driver)
14571456
"5m", 1, 0, INT_MAX, 0, &checkinterval);
14581457

14591458
(void) Ns_ScheduleProcEx(CheckPool, poolPtr, 0, &checkinterval, NULL);
1459+
Ns_RegisterProcInfo((ns_funcptr_t)CheckPool,
1460+
"nsdb:checkpool", CheckArgProc);
1461+
1462+
14601463
}
14611464
return poolPtr;
14621465
}

0 commit comments

Comments
 (0)