From c5432f7786072249f65a10ba75354bdf60689044 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Tue, 4 Aug 2026 03:38:58 +0000 Subject: [PATCH] feat(scheduler-core): implement clock virtualization and session timing (task 4.5) Adds xce_core_now() (new core_clock.c, kept separate from core.c so test_core_isolation.c's wall-clock scan still enforces zero direct clock_gettime()/time() calls elsewhere in the core): the two-anchor plus speed formula (virtual_clock_base + (elapsed * speed_num) / speed_den), covering all four modes (normal, discrete/real-time/fast- slow simulation) via four new atomic fields on xce_sched_core_t, defaulted to normal-mode (1/1 speed) in xce_sched_core_init(). requirements.md's literal tlog_reg_format_func(fn, core_ptr) call shape doesn't exist in the real vendored tlog library (registration takes only the callback; userptr is per-call-site, not bindable at registration) -- resolved with a module-level active-core pointer read by a new core-scoped format function, not wired into mylog_init()/ main.c yet. xce_core_go()/xce_core_end_session() (task 4.4) now stamp session_start/compute session_duration_ns via xce_core_now(), with their existing session-active/reentrancy behavior untouched. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_019dw5WnN3DXStaEaPYfACU1 --- .kiro/specs/scheduler-core/tasks.md | 4 +- src/scheduler/include/core.h | 98 +++++ src/scheduler/meson.build | 1 + src/scheduler/src/core.c | 12 + src/scheduler/src/core_clock.c | 233 ++++++++++ src/scheduler/src/core_session.c | 11 + src/scheduler/testsuite/meson.build | 20 + src/scheduler/testsuite/test_clock.c | 461 ++++++++++++++++++++ src/scheduler/testsuite/test_core_session.c | 14 +- 9 files changed, 849 insertions(+), 5 deletions(-) create mode 100644 src/scheduler/src/core_clock.c create mode 100644 src/scheduler/testsuite/test_clock.c diff --git a/.kiro/specs/scheduler-core/tasks.md b/.kiro/specs/scheduler-core/tasks.md index 1e5a7a58..9616ec94 100644 --- a/.kiro/specs/scheduler-core/tasks.md +++ b/.kiro/specs/scheduler-core/tasks.md @@ -115,12 +115,13 @@ - _Depends: 4.3_ - _Verified: 2026-08-03 — xce_core_go()/xce_core_end_session() (new core_session.c) implement the non-blocking session-start signal (-EINVAL on reentrant call, proven a true no-op via cbuf_tryget) and end-session cleanup; xce_core_set_decision_cb() registers the driver's on_decision callback (separate setter, not an xce_sched_core_init() param, to avoid touching its live sched_init() call site); XCE_DECISION_PREEMPT added to decision.h matching the DISPATCH/PEND/PREEMPT AC 6 table exactly. Decision-drain loop confirmed driver-owned (not a core function) via 3 independent requirements.md/design.md citations, re-derived independently by review. Additive only, sched_go/sched_begin_session/sched_end_session/sched_allocator/main.c untouched. REJECTED round 1 on a clang-format alignment regression in core.h (mid-struct insertion de-aligned 24 pre-existing lines) — fixed with clang-format -i, whitespace-only, re-verified 17/17 green._ -- [ ] 4.5 Implement clock virtualization and session timing +- [x] 4.5 Implement clock virtualization and session timing - Implement the virtualized clock accessor using the two-anchor-plus-speed formula, backed by atomically-updated fields; no direct wall-clock call anywhere else in the core - Register the core's own log-timestamp formatter, bound to the virtualized clock accessor instead of the logging library's default wall-clock read — this is the one third-party dependency inside the core that would otherwise call wall-clock time on every log line, silently reintroducing the exact dependency task 4.1 confirmed absent at link time - Track session start/end timestamps internally and compute session duration for diagnostics, exposed through the session summary - Observable: the clock accessor's output matches the documented formula for all four operating modes (normal, discrete simulation, real-time simulation, fast/slow simulation) given fixed anchor values; a log line emitted while the virtual clock is frozen at a fixed simulated timestamp shows that timestamp, not the real wall-clock time at the moment of the call - _Requirements: 5.3, 5.12_ + - _Verified: 2026-08-03 — xce_core_now() (new core_clock.c, kept out of core.c so test_core_isolation.c's wall-clock scan still passes) implements the exact two-anchor+speed formula; all 4 modes proven with fixed anchors, no sleep-based flakiness. requirements.md's literal tlog_reg_format_func(fn, core_ptr) call shape doesn't exist in the real vendored tlog API (verified against tlog.h: registration takes only the callback, userptr is per-call-site) — resolved via a module-level active-core pointer read by a new core-scoped format function, not wired into mylog_init()/main.c yet. session_start/session_duration_ns stamped correctly in xce_core_go()/xce_core_end_session() (task 4.4's behavior otherwise untouched). 18/18 scheduler suite passing, clang-format clean, review APPROVED first pass. Follow-up noted: core_clock.c is the 3rd core-adjacent file (after core_events.c, core_session.c) outside test_core_isolation.c's nm-based audit — manually verified clean, not mechanically enforced._ - _Depends: 4.1_ - [ ] 4.6 Core contract tests @@ -366,3 +367,4 @@ - Two follow-ups surfaced by task 2.4's review, not yet fixed (outside its file boundary): (1) `main.c` discards `sched_init()`'s return value, so a bad `job_pick_plugin` config fails `sched_init()` correctly but the process doesn't yet halt on it — needs a fast follow-up before relying on "fails startup" in production. (2) `pthread_testcancel()` in `builtin_fcfs_next_job()` is only at the loop entry/exit, not scattered through the queue/job walk (the walk holds `fcfs_plugin_data_t.lock` throughout, and this codebase has no `pthread_cleanup_push` precedent to safely unlock on mid-walk cancellation) — behaviorally inert today since `sched_queue_is_ready`/`sched_job_is_ready` are `return 1` stubs, but becomes a real cancellation-latency gap once Phase 2 implements real filtering. - Task 4.2's Req 5 AC 7 kvmgr iteration-order audit (scope: jobs/queues/users/projects, per design.md's bounded-scope note) found no unstable site — recorded durably as a comment in `core.c` above `xce_sched_core_init()`. One open gap surfaced but explicitly out of this task's scope: `core->workers` is iterated order-sensitively by `sched_collect_workers()` → `seqjob_allocator.c`'s first-fit `sched_try_alloc_on_hosts()`, and design.md itself says the full AC 7 guarantee must close "before Phase 3 simulation work depends on it" — needs a follow-up audit/fix (or an explicit documented exemption) before Phase 3 (tasks 7+) starts relying on scheduling determinism across worker selection. - Task 4.3 split its implementation into a NEW file `core_events.c` (not `core.c`, which design.md's File Structure Plan literally names) because implementing `xce_core_push_events()` directly in `core.c` would have pushed it to 977 lines, over this project's 800-line hard cap. `core.h` (the public contract) matches design.md's intent; only the `.c` file location differs. Worth reflecting in design.md next time it's touched. Also: `test_core_isolation.c`'s nm(1)-based zero-controller-I/O boundary audit (Req 5 AC 3) covers only `core.c`, not `core_events.c` — manually verified clean (no netio/xceapi/client/delay/idgen usage) but not mechanically enforced; extending that test to cover `core_events.c` would be a reasonable low-risk follow-up before later tasks add more logic to this file. +- Same pattern compounded across tasks 4.4 (`core_session.c`) and 4.5 (`core_clock.c`, which also genuinely NEEDS to be outside the wall-clock-call scan since it's the one file allowed to call `clock_gettime`) — `test_core_isolation.c` now covers only `core.c`, while three sibling files (`core_events.c`/`core_session.c`/`core_clock.c`) sit outside its mechanical audit, each manually verified clean but not enforced by a test. Worth a dedicated follow-up task extending the forbidden-header/forbidden-symbol half of the audit (not the wall-clock half, which `core_clock.c` must stay exempt from) to all `core_*.c` files before Phase 3 adds more. diff --git a/src/scheduler/include/core.h b/src/scheduler/include/core.h index b73980d9..727c27b1 100644 --- a/src/scheduler/include/core.h +++ b/src/scheduler/include/core.h @@ -23,6 +23,19 @@ * testsuite/test_core_isolation.c (source-text scan + an nm(1) undefined- * symbol audit of core.c's compiled object, the build-time proof this * task's Observable requires). + * + * One documented exception (task 4.5, Req 5 AC 3): the core's single + * sanctioned wall-clock call -- clock_gettime(CLOCK_MONOTONIC) inside + * xce_core_now() -- and its tlog format-function integration live in + * core_clock.c, a SEPARATE file from core.c, specifically so + * test_core_isolation.c's core.c-scoped "zero wall-clock calls" text scan + * keeps proving what it has always proven (core.c itself never reads real + * time) without needing to special-case the one legitimate call site AC 3 + * mandates. tlog (tinylog) is likewise an allowed core dependency as of + * this task -- AC 3's own "Third-party library constraint" section + * discusses the core registering a tlog format function -- distinct from + * the forbidden client.h/netio.h/xceapi.h/delay.h/idgen.h/xce/cluster.h + * list above, none of which tlog is part of. */ #include @@ -102,6 +115,55 @@ struct xce_sched_core_s { _Atomic int staging_merge_complete; /* 1 after staging merge completes */ select_eval_ctx_t* sel_eval_ctx; /* session-level memoisation context; NULL between sessions */ + /* + * Clock virtualization (Req 5 AC 3, scheduler-core spec, task 4.5): the + * core's ONLY sanctioned time source is xce_core_now() (core_clock.c), + * which computes virtual time from these four fields via the + * two-anchor + speed formula: + * + * wall_ns = clock_gettime(CLOCK_MONOTONIC) // the one wall-clock + * // call in the whole + * // core -- lives in + * // core_clock.c, NOT + * // core.c (core.c's own + * // zero-wall-clock + * // guarantee, enforced + * // by + * // test_core_isolation.c, + * // stays intact) + * elapsed = wall_ns - real_clock_base + * xce_core_now() = virtual_clock_base + (elapsed * speed_num) / speed_den + * + * Atomically updated by the driver AS A GROUP before each event + * dispatch (design.md's State Management note) -- xce_core_now() reads + * them lock-free, no mutex, safe from both the picker and allocator + * threads. xce_sched_core_init() seeds these to AC 3's Normal-mode row + * (virtual_clock_base=0, real_clock_base=0, speed_num=1, speed_den=1): + * degraded-to-real-wall-clock default, today's existing production + * behavior, preserved until a future simulation driver (Phase 3) + * explicitly reconfigures them. + */ + _Atomic uint64_t virtual_clock_base; + _Atomic uint64_t real_clock_base; + _Atomic uint64_t speed_num; + _Atomic uint64_t speed_den; + /* + * Session response-time diagnostics (Req 5 AC 12, task 4.5). Plain + * (non-atomic) fields -- touched only by the driver thread, inside + * xce_core_go()/xce_core_end_session() (core_session.c), the same + * single-writer discipline core->sel_eval_ctx above already follows. + * session_start is stamped at the top of xce_core_go(); the field name + * matches requirements.md's own pseudocode verbatim + * ("session_start = xce_core_now()"). session_duration_ns is computed + * at the top of xce_core_end_session() as xce_core_now() - + * session_start. Both are diagnostics only -- nothing in the + * scheduling/decision path reads them. The ReplaySession.summary + * SessionSummary wire struct these values eventually feed is explicitly + * OUT of this task's scope (Phase 3, recording/replay-format tasks + * 7.x) -- this struct only holds the plain numeric tracking. + */ + uint64_t session_start; + uint64_t session_duration_ns; }; /* @@ -302,4 +364,40 @@ extern int xce_core_go(xce_sched_core_t*); */ extern int xce_core_end_session(xce_sched_core_t*); +/* + * xce_core_now - Req 5 AC 3 (scheduler-core spec, task 4.5): the core's + * virtualized clock accessor, and the ONLY place inside the scheduler-core + * module family that calls clock_gettime() (implemented in core_clock.c, + * deliberately NOT core.c -- see this header's own top-of-file boundary + * comment and xce_sched_core_t's clock-field doc comment above for why). + * Computes virtual time via the two-anchor + speed formula from + * virtual_clock_base/real_clock_base/speed_num/speed_den, reading all four + * atomically (lock-free, safe from any thread). Returns 0 if core is NULL. + */ +extern uint64_t xce_core_now(xce_sched_core_t*); + +/* + * xce_core_set_active_for_logging / xce_core_register_tlog_format - Req 5 + * AC 3's tlog integration (task 4.5). See core_clock.c's own file header + * comment for the full reasoning behind this exact mechanism, including why + * it deliberately does NOT match AC 3's literal + * `tlog_reg_format_func(fn, core_ptr)` pseudocode -- that call shape does + * not exist in the real vendored tlog.h (`tlog_reg_format_func()` takes + * only the callback, no userptr-binding parameter; userptr is a per-call- + * site argument that flows through tlog_ext()/tlog_vext(), not something + * bindable once at registration time). + * + * xce_core_set_active_for_logging(core) sets (or, passed NULL, clears) a + * module-level "active core for logging" pointer that core_clock.c's + * registered tlog_format_func reads via xce_core_now() instead of + * info->time. xce_core_register_tlog_format() registers that format + * function with tlog via the real tlog_reg_format_func(). Neither is + * called from mylog_init()/main.c by this task -- wiring the live + * scheduler process over to this mechanism is a later task's job, + * consistent with tasks 4.1-4.4's additive-only, unwired-until-a-driver- + * exists pattern. + */ +extern void xce_core_set_active_for_logging(xce_sched_core_t*); +extern int xce_core_register_tlog_format(void); + #endif diff --git a/src/scheduler/meson.build b/src/scheduler/meson.build index e454edfa..12fc6aae 100644 --- a/src/scheduler/meson.build +++ b/src/scheduler/meson.build @@ -5,6 +5,7 @@ scheduler_srcs = [ 'src/core.c', 'src/core_events.c', 'src/core_session.c', + 'src/core_clock.c', 'src/decision.c', 'src/schedobj.c', 'src/plugin.c', diff --git a/src/scheduler/src/core.c b/src/scheduler/src/core.c index 22fee7fe..bf100c7a 100644 --- a/src/scheduler/src/core.c +++ b/src/scheduler/src/core.c @@ -127,6 +127,18 @@ int xce_sched_core_init(xce_sched_core_t* core) core->nextid = 1; core->configver = 0; + /* Req 5 AC 3 (scheduler-core spec, task 4.5): seed the clock atoms to + * AC 3's Normal-mode row. virtual_clock_base/real_clock_base are + * already correct from the memset() above (both 0); speed_num/ + * speed_den must be set explicitly to 1/1 -- memset() would otherwise + * leave them at 0/1, which is the FROZEN/discrete-simulation row, not + * Normal -- so a freshly initialized core degrades to real wall-clock + * time via xce_core_now() (today's existing production behavior), + * preserved until a future simulation driver (Phase 3) explicitly + * reconfigures these fields as a group. */ + atomic_store_explicit(&(core->speed_num), 1, memory_order_release); + atomic_store_explicit(&(core->speed_den), 1, memory_order_release); + xstring_table_init(1024 * 1024); mylock_init(&(core->lock)); diff --git a/src/scheduler/src/core_clock.c b/src/scheduler/src/core_clock.c new file mode 100644 index 00000000..15eebdfd --- /dev/null +++ b/src/scheduler/src/core_clock.c @@ -0,0 +1,233 @@ +#include +#include +#include +#include +#include + +#include "core.h" +#include "utils.h" + +/* + * core_clock.c - clock virtualization and the core's tlog format-function + * integration (scheduler-core spec, task 4.5, Req 5 AC 3). New file (not + * appended to core.c) for one deliberate reason: xce_core_now() must call + * clock_gettime(CLOCK_MONOTONIC) -- AC 3's own pseudocode names this the + * "only wall-clock call in the core" -- and test_core_isolation.c's + * regression guard (task 4.1) does a literal source-text scan of core.c + * for "clock_gettime(" (among other wall-clock substrings) and fails on + * any match, with no exception carve-out. Putting the one sanctioned call + * site in a SEPARATE file keeps that existing, already-passing test + * meaningful (core.c itself is still, and remains, provably wall-clock- + * free) while still giving the core exactly the single documented + * exception AC 3 requires. core.h's own boundary comment records this same + * reasoning for future readers. + * + * Public surface (core.h): xce_core_now(), xce_core_set_active_for_logging(), + * xce_core_register_tlog_format(). + * + * --- The tlog_reg_format_func() signature mismatch, and how this file + * --- resolves it (Req 5 AC 3's tlog integration bullet): + * + * requirements.md's own pseudocode reads: "The core shall register its own + * format function via `tlog_reg_format_func(fn, core_ptr)` where `core_ptr` + * is the `xce_sched_core_t*`." That exact call shape does not exist. The + * real vendored tlog.h (tinylog 1.0.0) declares: + * + * typedef int (*tlog_format_func)(char *buff, int maxlen, + * struct tlog_loginfo *info, void *userptr, const char *format, + * va_list ap); + * extern int tlog_reg_format_func(tlog_format_func callback); + * + * -- ONE argument, the callback, full stop. `userptr` is real, but it is a + * PER-CALL-SITE parameter that flows through tlog_ext()/tlog_vext() (every + * ERROR()/WARN()/INFO()/TRACE() macro ultimately calls tlog_ext(..., NULL, + * ...) with a hardcoded NULL userptr -- see utils.h's `tlog(level, format, + * ...)` macro), not something bindable once at registration time. + * src/lib/utils.c's existing my_tlog_format() already receives this same + * userptr parameter today and explicitly ignores it (xce_use(userptr)), + * reading info->time (populated by tlog itself from real wall-clock time) + * instead. + * + * Threading a `core` pointer through as userptr at every one of the + * scheduler's ERROR/WARN/INFO/TRACE call sites (rewriting the tlog(...) + * macro's hardcoded NULL to a real per-file/per-module core pointer, + * scheduler-wide) would be the only way to honor the pseudocode's literal + * userptr-per-call-site shape -- a massive, invasive, out-of-scope change + * this task's boundary does not license (task 4.5 is "clock virtualization + * and session timing", not "rewire every log call site in the scheduler"). + * + * The mechanism actually implemented here: a module-level pointer to "the + * core currently active for logging purposes" + * (g_active_core_for_logging), set via xce_core_set_active_for_logging() + * -- a small, core-scoped setter a driver calls once (this task does not + * wire it into mylog_init()/main.c; that remains a later task's job, same + * additive-only pattern as tasks 4.1-4.4). xce_core_tlog_format() -- the + * REAL tlog_format_func registered via xce_core_register_tlog_format() -- + * reads g_active_core_for_logging and, when non-NULL, formats + * xce_core_now(that core) instead of info->time. This is the only + * mechanism that actually exists in tlog's real API without a scheduler- + * wide invasive rewrite: `tlog_loginfo`/`info->time` are populated by tlog + * itself, inside tlog_ext(), before any format function ever runs (there is + * no seam to "pre-populate" info->time from the caller's side either -- + * tlog_ext()'s implementation, not this file, owns that population). + */ + +/* Nanoseconds per second -- named per this project's "no hardcoded values" + * convention; used both by xce_core_now()'s wall-clock read and + * ns_to_tlog_time()'s epoch-seconds/microseconds split below. */ +#define CORE_CLOCK_NSEC_PER_SEC 1000000000ULL + +uint64_t xce_core_now(xce_sched_core_t* core) +{ + struct timespec ts; + uint64_t wall_ns; + uint64_t vbase; + uint64_t rbase; + uint64_t num; + uint64_t den; + uint64_t elapsed; + + if (core == NULL) { + return 0; + } + + /* The ONE wall-clock call in the entire scheduler-core module family + * (Req 5 AC 3's pseudocode: "only wall-clock call in the core"). See + * this file's own header comment for why it lives here and not + * core.c. */ + clock_gettime(CLOCK_MONOTONIC, &ts); + wall_ns = ((uint64_t)ts.tv_sec * CORE_CLOCK_NSEC_PER_SEC) + + (uint64_t)ts.tv_nsec; + + vbase = atomic_load_explicit(&(core->virtual_clock_base), + memory_order_acquire); + rbase + = atomic_load_explicit(&(core->real_clock_base), memory_order_acquire); + num = atomic_load_explicit(&(core->speed_num), memory_order_acquire); + den = atomic_load_explicit(&(core->speed_den), memory_order_acquire); + + if (den == 0) { + /* Defensive: AC 3's documented mode table never sets speed_den to + * 0 (discrete-simulation freezes via speed_num=0, not speed_den=0) + * -- this guard only prevents undefined-behavior-by-malformed- + * input, it is never expected to trigger in a correct driver. */ + den = 1; + } + + elapsed = wall_ns - rbase; + + return vbase + (elapsed * num) / den; +} + +/* + * g_active_core_for_logging - see this file's header comment for the full + * tlog_reg_format_func() signature-mismatch reasoning. NULL until a driver + * calls xce_core_set_active_for_logging(); xce_core_tlog_format() falls + * back to info->time (tlog's own real-wall-clock read) while NULL, + * matching src/lib/utils.c's default formatter's behavior exactly. + */ +static _Atomic(xce_sched_core_t*) g_active_core_for_logging = NULL; + +void xce_core_set_active_for_logging(xce_sched_core_t* core) +{ + atomic_store_explicit(&g_active_core_for_logging, core, + memory_order_release); +} + +/* + * ns_to_tlog_time - converts a virtualized-clock nanoseconds-since-epoch + * value (xce_core_now()'s return) into struct tlog_time via gmtime_r(), per + * Req 5 AC 3's own text: "converting nanoseconds to struct tm fields via + * gmtime_r() (deterministic -- pure computation)". This is NOT a + * wall-clock read: gmtime_r() performs a pure calendar conversion on a + * value already obtained through xce_core_now() -- no + * time()/clock_gettime()/gettimeofday() call appears here. + */ +static void ns_to_tlog_time(uint64_t ns, struct tlog_time* out) +{ + time_t secs = (time_t)(ns / CORE_CLOCK_NSEC_PER_SEC); + struct tm gmt; + + gmtime_r(&secs, &gmt); + + out->year = gmt.tm_year + 1900; + out->mon = (unsigned char)(gmt.tm_mon + 1); + out->mday = (unsigned char)gmt.tm_mday; + out->hour = (unsigned char)gmt.tm_hour; + out->min = (unsigned char)gmt.tm_min; + out->sec = (unsigned char)gmt.tm_sec; + out->usec = (unsigned int)((ns % CORE_CLOCK_NSEC_PER_SEC) / 1000ULL); +} + +/* + * xce_core_tlog_format - Req 5 AC 3's tlog integration point (task 4.5). + * Mirrors src/lib/utils.c's my_tlog_format() prefix layout EXACTLY (same + * two snprintf format strings -- file:line for sub-INFO levels, func name + * otherwise -- same getpid()/level-string fields) with exactly one + * substitution: the timestamp source. Where my_tlog_format() always reads + * info->time (populated by tlog itself from real wall-clock time at the + * log call site), this function reads xce_core_now(g_active_core_for_logging) + * when an active core is registered -- giving every ERROR/WARN/INFO/TRACE + * call site inside the core the virtualized timestamp for free, with zero + * call-site changes. Falls back to info->time when no active core is + * registered (NULL), identical to today's default behavior -- see this + * file's header comment for the full reasoning. + */ +static int xce_core_tlog_format(char* buff, int maxlen, + struct tlog_loginfo* info, void* userptr, + const char* fmt, va_list ap) +{ + xce_sched_core_t* core; + struct tlog_time virt_time; + struct tlog_time* tm; + int len; + int total_len = 0; + + xce_use(userptr); + + core = atomic_load_explicit(&g_active_core_for_logging, + memory_order_acquire); + if (core != NULL) { + ns_to_tlog_time(xce_core_now(core), &virt_time); + tm = &virt_time; + } else { + tm = &(info->time); + } + + if (info->level < TLOG_INFO) { + len = snprintf( + buff, maxlen, + "[%.4d-%.2d-%.2d %.2d:%.2d:%.2d,%.3d] [%5d] [%6s] [%17s:%-4d] ", + tm->year, tm->mon, tm->mday, tm->hour, tm->min, tm->sec, + tm->usec / 1000, getpid(), tlog_get_level_string(info->level), + info->file, info->line); + } else { + len = snprintf( + buff, maxlen, + "[%.4d-%.2d-%.2d %.2d:%.2d:%.2d,%.3d] [%5d] [%6s] [%22s] ", + tm->year, tm->mon, tm->mday, tm->hour, tm->min, tm->sec, + tm->usec / 1000, getpid(), tlog_get_level_string(info->level), + info->func); + } + + if (len < 0 || len >= maxlen) { + return -1; + } + buff += len; + total_len += len; + maxlen -= len; + + /* format log message */ + len = vsnprintf(buff, maxlen, fmt, ap); + if (len < 0 || len == maxlen) { + return -1; + } + total_len += len; + + return total_len; +} + +int xce_core_register_tlog_format(void) +{ + return tlog_reg_format_func(xce_core_tlog_format); +} diff --git a/src/scheduler/src/core_session.c b/src/scheduler/src/core_session.c index 99f6184b..611f8ecf 100644 --- a/src/scheduler/src/core_session.c +++ b/src/scheduler/src/core_session.c @@ -362,6 +362,11 @@ int xce_core_go(xce_sched_core_t* core) atomic_store_explicit(&(core->session_active), 1, memory_order_release); + /* Req 5 AC 12 (scheduler-core spec, task 4.5): stamp session_start via + * the virtualized clock accessor -- never a direct wall-clock call + * (this file's own boundary comment, above). */ + core->session_start = xce_core_now(core); + core_begin_session_internal(core); /* NON-BLOCKING: wbuf has capacity 1 and is empty between sessions (the @@ -382,6 +387,12 @@ int xce_core_end_session(xce_sched_core_t* core) core_end_session_internal(core); + /* Req 5 AC 12 (scheduler-core spec, task 4.5): session_duration_ns = + * xce_core_now() - session_start, computed before session_active + * clears (matches core_go()'s ordering: state pertaining to THIS + * session is finalized before the session is marked inactive). */ + core->session_duration_ns = xce_core_now(core) - core->session_start; + atomic_store_explicit(&(core->session_active), 0, memory_order_release); return 0; diff --git a/src/scheduler/testsuite/meson.build b/src/scheduler/testsuite/meson.build index 435f250a..81825777 100644 --- a/src/scheduler/testsuite/meson.build +++ b/src/scheduler/testsuite/meson.build @@ -259,6 +259,23 @@ sched_core_session_test = executable( dependencies: [scheduler_test_deps], install: false) +# Contract test for clock virtualization and session timing (scheduler-core +# spec, task 4.5, Req 5 AC 3 / AC 12): xce_core_now()'s two-anchor + speed +# formula for all four documented modes, xce_core_tlog_format()'s tlog +# integration (frozen virtual time shown instead of info->time's real +# wall-clock read), and session_start/session_duration_ns tracking across a +# real xce_core_go()/xce_core_end_session() cycle. Same white-box #include +# pattern as test_core_session.c (pulls ../src/core.c, ../src/core_session.c, +# and ../src/decision.c into this TU) PLUS ../src/core_clock.c (this task's +# new file -- see that file's own header comment for why xce_core_now()/ +# the tlog format function live there, not in core.c). +sched_core_clock_test = executable( + 'sched_core_clock_test', + ['test_clock.c'], + include_directories:[incdir], + dependencies: [scheduler_test_deps], + install: false) + # Register as meson tests so `meson test --suite scheduler` runs them all. # detect_leaks=0 matches the suite convention (fixtures are not torn down). test('scheduler test', scheduler_test, suite: 'scheduler', @@ -301,3 +318,6 @@ test('scheduler core events test', test('scheduler core session test', sched_core_session_test, suite: 'scheduler', env: ['ASAN_OPTIONS=detect_leaks=0']) +test('scheduler core clock test', + sched_core_clock_test, suite: 'scheduler', + env: ['ASAN_OPTIONS=detect_leaks=0']) diff --git a/src/scheduler/testsuite/test_clock.c b/src/scheduler/testsuite/test_clock.c new file mode 100644 index 00000000..4db982c4 --- /dev/null +++ b/src/scheduler/testsuite/test_clock.c @@ -0,0 +1,461 @@ +/* + * test_clock.c - contract test for clock virtualization and session timing + * (scheduler-core spec, task 4.5, Req 5 AC 3 / AC 12). + * + * Observable under test: + * - xce_core_now() implements the two-anchor + speed formula (Req 5 AC 3) + * exactly, for all four documented operating modes (normal, discrete + * simulation, real-time simulation, fast/slow simulation), given fixed + * anchor values -- no sleep-based real-elapsed-time assertions. Where a + * mode's own definition makes the output track real wall-clock time + * (normal, real-time, fast/slow), the test brackets the result between + * two back-to-back CLOCK_MONOTONIC reads taken immediately before/after + * the call -- deterministic (time is monotonic, so the bracket always + * holds) and fast (nanoseconds of real work between the two reads), NOT + * the sleep-then-check-approximate-elapsed pattern this task forbids. + * Discrete-simulation (frozen, speed=0/1) collapses the bracket to an + * exact equality since elapsed*0/den is always 0 regardless of when the + * test runs. + * - xce_core_tlog_format() (core_clock.c's registered tlog_format_func) + * reads xce_core_now() of the module-level "active core for logging" + * when one is registered, IGNORING info->time (which tlog itself + * populates from real wall-clock time at the call site) -- so a log + * line formatted while the virtual clock is frozen shows the frozen + * simulated timestamp, not real wall-clock time. Falls back to + * info->time when no active core is registered (matching today's + * default formatter's behavior). + * - xce_core_register_tlog_format() really registers with the real + * tlog_reg_format_func() (proves xce_core_tlog_format's signature is + * genuinely tlog_format_func-compatible -- this file would fail to + * compile otherwise -- and that tlog accepts it at runtime). + * - session_start is stamped at the top of xce_core_go() and + * session_duration_ns is computed at the top of xce_core_end_session() + * as xce_core_now() - session_start (Req 5 AC 12), exercised through + * the REAL xce_core_go()/xce_core_end_session() (core_session.c) with + * the core's clock frozen (discrete-simulation mode) so both the + * zero-duration case (AC 12's own "fast mode ... duration_ns is + * typically 0" note) and a nonzero case (clock advanced between go() + * and end_session(), the same anchor-update-between-events pattern a + * real driver follows) are fully deterministic. + * + * White-box #include of ../src/core_clock.c (xce_core_now(), + * xce_core_tlog_format(), g_active_core_for_logging, + * xce_core_register_tlog_format() -- same convention as every other + * white-box test in this directory) PLUS ../src/core.c, ../src/core_session.c, + * and ../src/decision.c (same set test_core_session.c already pulls in) so + * the session-timing tests exercise the REAL xce_core_go()/ + * xce_core_end_session(), not a re-implementation. The kill_sched_ family, + * plugin_unregister, and sched_worker_release_host_ctx stubs below exist + * purely to satisfy the linker for xce_sched_core_init()'s + * kvmgr_params_t.datakiller fields and core_session.c's core_reset_workers() + * -- never actually invoked, same rationale test_core_session.c's own header + * comment documents. + */ +#include +#include +#include +#include + +#include + +#include "preason.h" + +/* Pull in the real xce_core_now()/xce_core_tlog_format()/ + * xce_core_register_tlog_format()/xce_sched_core_init()/xce_core_go()/ + * xce_core_end_session() under test into this TU (white-box #include). */ +#include "../src/core.c" +#include "../src/core_clock.c" +#include "../src/core_session.c" +#include "../src/decision.c" + +void kill_sched_job(void* arg) { (void)arg; } +void kill_sched_queue(void* arg) { (void)arg; } +void kill_sched_worker(void* arg) { (void)arg; } +void kill_sched_user(void* arg) { (void)arg; } +void kill_sched_project(void* arg) { (void)arg; } +void kill_sched_resval(xce_val_t* val) { (void)val; } +void plugin_unregister(void* arg) { (void)arg; } +void sched_worker_release_host_ctx(xce_sched_worker_t* w) { (void)w; } + +void setUp(void) { return; } +void tearDown(void) { return; } + +/* ---------------------------------------------------------------------- */ +/* Helpers */ +/* ---------------------------------------------------------------------- */ + +#define TEST_NSEC_PER_SEC 1000000000ULL + +static uint64_t test_monotonic_ns(void) +{ + struct timespec ts; + + clock_gettime(CLOCK_MONOTONIC, &ts); + return ((uint64_t)ts.tv_sec * TEST_NSEC_PER_SEC) + (uint64_t)ts.tv_nsec; +} + +static void set_clock_atoms(xce_sched_core_t* core, uint64_t vbase, + uint64_t rbase, uint64_t num, uint64_t den) +{ + atomic_store_explicit(&(core->virtual_clock_base), vbase, + memory_order_release); + atomic_store_explicit(&(core->real_clock_base), rbase, + memory_order_release); + atomic_store_explicit(&(core->speed_num), num, memory_order_release); + atomic_store_explicit(&(core->speed_den), den, memory_order_release); +} + +static void fixture_init(xce_sched_core_t* core) +{ + int rc = xce_sched_core_init(core); + TEST_ASSERT_EQUAL_INT(0, rc); +} + +/* ---------------------------------------------------------------------- */ +/* xce_core_now() -- two-anchor + speed formula (Req 5 AC 3) */ +/* ---------------------------------------------------------------------- */ + +static void test_xce_core_now_null_core_returns_zero(void) +{ + TEST_ASSERT_EQUAL_UINT64(0, xce_core_now(NULL)); +} + +static void test_xce_core_now_normal_mode_matches_wall_clock(void) +{ + /* Normal mode (AC 3's table): virtual_clock_base=0, real_clock_base=0, + * speed=1/1 -- degraded to real wall clock: 0 + (wall-0)*1/1 = wall. */ + xce_sched_core_t core; + uint64_t before, result, after; + + memset(&core, 0, sizeof(core)); + set_clock_atoms(&core, 0, 0, 1, 1); + + before = test_monotonic_ns(); + result = xce_core_now(&core); + after = test_monotonic_ns(); + + TEST_ASSERT_TRUE(result >= before); + TEST_ASSERT_TRUE(result <= after); +} + +static void test_xce_core_now_discrete_simulation_frozen_at_event_ts(void) +{ + /* Simulation discrete (AC 3's table): virtual_clock_base=event ts, + * real_clock_base=wall at load, speed=0/1 -- frozen at ts regardless of + * real elapsed time (elapsed * 0 / 1 == 0 always). Exact equality, no + * bracket needed -- the whole point of this mode. */ + xce_sched_core_t core; + const uint64_t EVENT_TS = 1700000000123456789ULL; + uint64_t result; + + memset(&core, 0, sizeof(core)); + set_clock_atoms(&core, EVENT_TS, test_monotonic_ns(), 0, 1); + + result = xce_core_now(&core); + TEST_ASSERT_EQUAL_UINT64(EVENT_TS, result); + + /* Re-reading later still returns the identical frozen value -- proves + * "time does not advance between events", not a one-shot coincidence. */ + result = xce_core_now(&core); + TEST_ASSERT_EQUAL_UINT64(EVENT_TS, result); +} + +static void +test_xce_core_now_realtime_simulation_tracks_wall_clock_from_anchor(void) +{ + /* Simulation real-time (AC 3's table): virtual_clock_base=snapshot ts, + * real_clock_base=wall at load, speed=1/1 -- tracks wall clock from the + * virtual anchor: result is between [snapshot_ts, snapshot_ts + + * (after-before)]. */ + xce_sched_core_t core; + const uint64_t SNAPSHOT_TS = 500000000000ULL; + uint64_t before, result, after; + + memset(&core, 0, sizeof(core)); + before = test_monotonic_ns(); + set_clock_atoms(&core, SNAPSHOT_TS, before, 1, 1); + + result = xce_core_now(&core); + after = test_monotonic_ns(); + + TEST_ASSERT_TRUE(result >= SNAPSHOT_TS); + TEST_ASSERT_TRUE(result <= SNAPSHOT_TS + (after - before)); +} + +static void test_xce_core_now_fast_simulation_scales_up_by_speed(void) +{ + /* Simulation fast (AC 3's table): speed=N/1 -- runs N times faster than + * wall clock. Bracket scaled by N. */ + xce_sched_core_t core; + const uint64_t SNAPSHOT_TS = 1000ULL; + const uint64_t N = 1000ULL; + uint64_t before, result, after; + + memset(&core, 0, sizeof(core)); + before = test_monotonic_ns(); + set_clock_atoms(&core, SNAPSHOT_TS, before, N, 1); + + result = xce_core_now(&core); + after = test_monotonic_ns(); + + TEST_ASSERT_TRUE(result >= SNAPSHOT_TS); + TEST_ASSERT_TRUE(result <= SNAPSHOT_TS + (after - before) * N); +} + +static void test_xce_core_now_slow_simulation_scales_down_by_speed(void) +{ + /* Simulation slow (AC 3's table): speed=1/N -- runs N times slower than + * wall clock. Bracket scaled down by N (+1 for integer-division + * rounding slack). */ + xce_sched_core_t core; + const uint64_t SNAPSHOT_TS = 1000ULL; + const uint64_t N = 1000ULL; + uint64_t before, result, after; + + memset(&core, 0, sizeof(core)); + before = test_monotonic_ns(); + set_clock_atoms(&core, SNAPSHOT_TS, before, 1, N); + + result = xce_core_now(&core); + after = test_monotonic_ns(); + + TEST_ASSERT_TRUE(result >= SNAPSHOT_TS); + TEST_ASSERT_TRUE(result <= SNAPSHOT_TS + (after - before) / N + 1); +} + +/* ---------------------------------------------------------------------- */ +/* Clock virtualization is atomically updated as a group (Req 5 AC 3) */ +/* ---------------------------------------------------------------------- */ + +static void test_xce_sched_core_init_seeds_normal_mode_defaults(void) +{ + /* xce_sched_core_init() (core.c, task 4.5) must seed the clock atoms + * to AC 3's Normal-mode row -- preserving today's real-wall-clock + * default until a simulation driver reconfigures them. */ + xce_sched_core_t core; + + fixture_init(&core); + + TEST_ASSERT_EQUAL_UINT64(0, atomic_load_explicit(&(core.virtual_clock_base), + memory_order_acquire)); + TEST_ASSERT_EQUAL_UINT64( + 0, atomic_load_explicit(&(core.real_clock_base), memory_order_acquire)); + TEST_ASSERT_EQUAL_UINT64( + 1, atomic_load_explicit(&(core.speed_num), memory_order_acquire)); + TEST_ASSERT_EQUAL_UINT64( + 1, atomic_load_explicit(&(core.speed_den), memory_order_acquire)); +} + +/* ---------------------------------------------------------------------- */ +/* tlog format integration (Req 5 AC 3) */ +/* ---------------------------------------------------------------------- */ + +static int call_format(char* buff, int maxlen, struct tlog_loginfo* info, + void* userptr, const char* fmt, ...) +{ + va_list ap; + int rc; + + va_start(ap, fmt); + rc = xce_core_tlog_format(buff, maxlen, info, userptr, fmt, ap); + va_end(ap); + + return rc; +} + +static void test_tlog_format_shows_frozen_virtual_time_not_infotime(void) +{ + /* Freeze the active core's virtual clock at a known simulated instant + * (2033-05-18 03:04:05 UTC) and set info->time to a deliberately + * DIFFERENT, real-looking wall-clock value (1999-01-01) -- proving the + * formatter reads the frozen simulated time, not info->time. */ + xce_sched_core_t core; + struct tlog_loginfo info; + char buff[256]; + int rc; + const uint64_t FROZEN_NS = 2000000000ULL * TEST_NSEC_PER_SEC; + /* 2033-05-18ish -- exact date not asserted; only that it is NOT the + * info->time value below. */ + + memset(&core, 0, sizeof(core)); + set_clock_atoms(&core, FROZEN_NS, test_monotonic_ns(), 0, 1); + + memset(&info, 0, sizeof(info)); + info.level = TLOG_INFO; + info.file = "test.c"; + info.func = "test_func"; + info.line = 42; + info.time.year = 1999; + info.time.mon = 1; + info.time.mday = 1; + info.time.hour = 0; + info.time.min = 0; + info.time.sec = 0; + info.time.usec = 0; + + xce_core_set_active_for_logging(&core); + + rc = call_format(buff, sizeof(buff), &info, NULL, "hello %d", 7); + TEST_ASSERT_TRUE(rc > 0); + TEST_ASSERT_NOT_NULL(strstr(buff, "hello 7")); + TEST_ASSERT_NULL_MESSAGE( + strstr(buff, "1999"), + "formatted log line must NOT show info->time's wall-clock year " + "while the virtual clock is frozen"); + + xce_core_set_active_for_logging(NULL); +} + +static void test_tlog_format_frozen_time_is_stable_across_calls(void) +{ + /* Formatting twice, with no change to the frozen anchors, must produce + * an IDENTICAL timestamp both times -- the direct proof that the shown + * timestamp is the frozen simulated ts, not whatever the real clock + * happens to read at each call. */ + xce_sched_core_t core; + struct tlog_loginfo info; + char buff1[256]; + char buff2[256]; + char* ts_end1; + char* ts_end2; + const uint64_t FROZEN_NS = 1234567890ULL * TEST_NSEC_PER_SEC; + + memset(&core, 0, sizeof(core)); + set_clock_atoms(&core, FROZEN_NS, test_monotonic_ns(), 0, 1); + + memset(&info, 0, sizeof(info)); + info.level = TLOG_INFO; + info.func = "test_func"; + + xce_core_set_active_for_logging(&core); + + call_format(buff1, sizeof(buff1), &info, NULL, "first"); + call_format(buff2, sizeof(buff2), &info, NULL, "second"); + + xce_core_set_active_for_logging(NULL); + + /* Both lines share the same "[YYYY-MM-DD HH:MM:SS,mmm]" prefix -- find + * the closing bracket of the timestamp portion and compare up to it. */ + ts_end1 = strchr(buff1, ']'); + ts_end2 = strchr(buff2, ']'); + TEST_ASSERT_NOT_NULL(ts_end1); + TEST_ASSERT_NOT_NULL(ts_end2); + TEST_ASSERT_EQUAL_INT(ts_end1 - buff1, ts_end2 - buff2); + TEST_ASSERT_TRUE(strncmp(buff1, buff2, (size_t)(ts_end1 - buff1)) == 0); +} + +static void test_tlog_format_falls_back_to_infotime_when_no_active_core(void) +{ + /* No active core registered (NULL, the module's own default) -- + * xce_core_tlog_format() must fall back to info->time, matching + * src/lib/utils.c's my_tlog_format() default behavior exactly. */ + struct tlog_loginfo info; + char buff[256]; + int rc; + + xce_core_set_active_for_logging(NULL); + + memset(&info, 0, sizeof(info)); + info.level = TLOG_INFO; + info.func = "test_func"; + info.time.year = 2077; + info.time.mon = 6; + info.time.mday = 15; + info.time.hour = 12; + info.time.min = 30; + info.time.sec = 45; + info.time.usec = 0; + + rc = call_format(buff, sizeof(buff), &info, NULL, "fallback"); + TEST_ASSERT_TRUE(rc > 0); + TEST_ASSERT_NOT_NULL(strstr(buff, "2077-06-15")); +} + +static void test_xce_core_register_tlog_format_succeeds(void) +{ + int rc = xce_core_register_tlog_format(); + TEST_ASSERT_EQUAL_INT(0, rc); +} + +/* ---------------------------------------------------------------------- */ +/* Session timing (Req 5 AC 12) */ +/* ---------------------------------------------------------------------- */ + +static void test_session_duration_zero_when_clock_frozen_across_session(void) +{ + /* AC 12's own note: "in fast mode the virtual clock freezes during + * core_go() so duration_ns is typically 0". Discrete-simulation mode + * (speed=0/1) reproduces exactly that: xce_core_now() returns the same + * frozen value at both core_go() and core_end_session(). */ + xce_sched_core_t core; + int rc; + int go = 0; + const uint64_t FROZEN_TS = 42424242ULL; + + fixture_init(&core); + set_clock_atoms(&core, FROZEN_TS, test_monotonic_ns(), 0, 1); + + rc = xce_core_go(&core); + TEST_ASSERT_EQUAL_INT(0, rc); + TEST_ASSERT_EQUAL_UINT64(FROZEN_TS, core.session_start); + + cbuf_tryget(&(core.wbuf), &go); /* drain the signal, not under test here */ + + rc = xce_core_end_session(&core); + TEST_ASSERT_EQUAL_INT(0, rc); + TEST_ASSERT_EQUAL_UINT64(0, core.session_duration_ns); +} + +static void +test_session_duration_reflects_clock_advance_between_go_and_end(void) +{ + /* Models a real driver updating the clock atoms between events (AC 3: + * "the driver atomically updates all four fields before each event + * dispatch") -- the virtual clock advances by a known, fixed amount + * between core_go() and core_end_session(), fully deterministic (no + * sleep, no real elapsed time involved). */ + xce_sched_core_t core; + int rc; + int go = 0; + const uint64_t START_TS = 1000000ULL; + const uint64_t ADVANCE = 250000ULL; + + fixture_init(&core); + set_clock_atoms(&core, START_TS, test_monotonic_ns(), 0, 1); + + rc = xce_core_go(&core); + TEST_ASSERT_EQUAL_INT(0, rc); + TEST_ASSERT_EQUAL_UINT64(START_TS, core.session_start); + + cbuf_tryget(&(core.wbuf), &go); + + /* Driver advances virtual_clock_base before the next dispatch -- still + * frozen (speed 0/1) at the new value, so end_session() sees exactly + * START_TS + ADVANCE, deterministically. */ + atomic_store_explicit(&(core.virtual_clock_base), START_TS + ADVANCE, + memory_order_release); + + rc = xce_core_end_session(&core); + TEST_ASSERT_EQUAL_INT(0, rc); + TEST_ASSERT_EQUAL_UINT64(ADVANCE, core.session_duration_ns); +} + +int main(void) +{ + UNITY_BEGIN(); + RUN_TEST(test_xce_core_now_null_core_returns_zero); + RUN_TEST(test_xce_core_now_normal_mode_matches_wall_clock); + RUN_TEST(test_xce_core_now_discrete_simulation_frozen_at_event_ts); + RUN_TEST( + test_xce_core_now_realtime_simulation_tracks_wall_clock_from_anchor); + RUN_TEST(test_xce_core_now_fast_simulation_scales_up_by_speed); + RUN_TEST(test_xce_core_now_slow_simulation_scales_down_by_speed); + RUN_TEST(test_xce_sched_core_init_seeds_normal_mode_defaults); + RUN_TEST(test_tlog_format_shows_frozen_virtual_time_not_infotime); + RUN_TEST(test_tlog_format_frozen_time_is_stable_across_calls); + RUN_TEST(test_tlog_format_falls_back_to_infotime_when_no_active_core); + RUN_TEST(test_xce_core_register_tlog_format_succeeds); + RUN_TEST(test_session_duration_zero_when_clock_frozen_across_session); + RUN_TEST(test_session_duration_reflects_clock_advance_between_go_and_end); + return UNITY_END(); +} diff --git a/src/scheduler/testsuite/test_core_session.c b/src/scheduler/testsuite/test_core_session.c index f6f7ec0a..26dfc196 100644 --- a/src/scheduler/testsuite/test_core_session.c +++ b/src/scheduler/testsuite/test_core_session.c @@ -27,11 +27,16 @@ * - xce_core_end_session() clears session_active back to 0, unblocking * the next xce_core_go() call. * - * White-box #include of ../src/core.c, ../src/core_session.c, and - * ../src/decision.c (same convention as test_core_events.c/ - * test_core_jbuf_capacity_pin.c) so this test exercises the REAL - * xce_sched_core_init()/xce_core_go()/xce_core_end_session()/ + * White-box #include of ../src/core.c, ../src/core_session.c, + * ../src/core_clock.c, and ../src/decision.c (same convention as + * test_core_events.c/test_core_jbuf_capacity_pin.c) so this test exercises + * the REAL xce_sched_core_init()/xce_core_go()/xce_core_end_session()/ * xce_core_set_decision_cb()/make_*_decision(), not a re-implementation. + * core_clock.c joined this file's #include list in task 4.5 (scheduler-core + * spec): xce_core_go()/xce_core_end_session() now call xce_core_now() + * (Req 5 AC 12 session timing), which core_clock.c is the only TU that + * defines -- see test_clock.c for that function's own dedicated contract + * tests; this file does not re-test the clock formula itself. * Unlike test_core_events.c, this file does not need core_events.c or a * working picker plugin resolution -- xce_core_go()/xce_core_end_session() * never call sched_resolve_job_picker() (verified: grep confirms neither @@ -54,6 +59,7 @@ * xce_core_end_session()/xce_core_set_decision_cb()/make_*_decision() * under test into this TU (white-box #include). */ #include "../src/core.c" +#include "../src/core_clock.c" #include "../src/core_session.c" #include "../src/decision.c"