lei.chen/myxce
1
0
Fork 1
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions
myxce/src/scheduler/testsuite/test_clock.c
Rongsong Shen e56f27f997
test(scheduler): check only the timestamp field in the frozen tlog format test (bug-1924) 
test_tlog_format_shows_frozen_virtual_time_not_infotime asserted that
"1999" (info->time's year) appears nowhere in the formatted line, but
the line also carries getpid(), so the test failed whenever its PID
contained 1999. It now asserts the exact frozen timestamp field.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
2026-10-08 09:50:36 +00:00

517 lines
20 KiB
C
Raw Blame History

/*
* 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, given fixed anchor values -- no sleep-based
* real-elapsed-time assertions. The product uses two settings of the
* speed atoms: 1/1 in normal mode and 0/1 (frozen) in simulation mode
* (scheduler-sim-discrete-clock: the simulator has no speed modes).
* Three further tests exercise the formula itself with an arbitrary
* virtual anchor and with ratios 1/1, N/1 and 1/N; they test the
* arithmetic, not any product mode. Where the ratio is non-zero the
* output tracks real wall-clock time, so 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.
* Simulation mode (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 simulation-mode bullet: the clock moves
* only at recorded timestamps, so a session's duration_ns is 0) 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 <stdarg.h>
#include <stdint.h>
#include <string.h>
#include <time.h>
#include <unity/unity.h>
#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_unit_ratio_tracks_wall_clock_from_virtual_anchor(void)
{
/* Formula test: an arbitrary virtual_clock_base, real_clock_base=wall
* now, speed=1/1 -- the result advances with the wall clock from the
* virtual anchor: it lies in [anchor, anchor + (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_ratio_above_one_scales_elapsed_up(void)
{
/* Formula test: speed=N/1 -- elapsed wall time is multiplied by N.
* 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_ratio_below_one_scales_elapsed_down(void)
{
/* Formula test: speed=1/N -- elapsed wall time is divided by N.
* 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));
}
/* ---------------------------------------------------------------------- */
/* xce_core_set_wallclock_anchor() -- normal-mode epoch seeding (bug-1584) */
/* ---------------------------------------------------------------------- */
static uint64_t test_epoch_ns(void)
{
struct timespec ts;
clock_gettime(CLOCK_REALTIME, &ts);
return ((uint64_t)ts.tv_sec * TEST_NSEC_PER_SEC) + (uint64_t)ts.tv_nsec;
}
static void test_xce_core_set_wallclock_anchor_seeds_real_epoch_time(void)
{
/* bug-1584: xce_sched_core_init() alone leaves xce_core_now() returning
* raw CLOCK_MONOTONIC-since-boot nanoseconds (see
* test_xce_sched_core_init_seeds_normal_mode_defaults above) -- NOT
* epoch time, which every real consumer of a normal-mode timestamp
* needs (recording.c's record_start_ts, SchedAdminReply.startedAt,
* documented in controller.capnp as "nanoseconds since epoch").
* xce_core_set_wallclock_anchor() is the fix: bracket its effect on
* xce_core_now() between two back-to-back CLOCK_REALTIME reads taken
* immediately before/after the call -- deterministic (real time only
* moves forward) and immune to sleep-based flakiness. Before this fix,
* `result` would be a small monotonic-since-boot value, far below
* `before` (a real epoch value ~1.7e18 ns as of 2026) -- this bracket
* fails loudly on that regression rather than passing by coincidence. */
xce_sched_core_t core;
uint64_t before, result, after;
fixture_init(&core);
before = test_epoch_ns();
xce_core_set_wallclock_anchor(&core);
result = xce_core_now(&core);
after = test_epoch_ns();
TEST_ASSERT_TRUE(result >= before);
TEST_ASSERT_TRUE(result <= after);
}
static void test_xce_core_set_wallclock_anchor_null_core_is_a_safe_noop(void)
{
/* Mirrors xce_core_now(NULL)'s defensive contract -- no crash. */
xce_core_set_wallclock_anchor(NULL);
}
/* ---------------------------------------------------------------------- */
/* 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-18 03:33:20 UTC -- asserted exactly 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"));
/* Only the timestamp field is checked: the rest of the line carries
* getpid(), which itself contains "1999" for some PIDs (bug-1924).
* FROZEN_NS is 2000000000 s after the epoch, formatted with gmtime_r
* (core_clock.c ns_to_tlog_time), so the field is exact. */
TEST_ASSERT_EQUAL_STRING_LEN_MESSAGE(
"[2033-05-18 03:33:20,000] ", buff, 26,
"formatted log line must show the frozen virtual time, not "
"info->time's wall-clock time");
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 simulation-mode bullet: the virtual clock moves only when
* the replay sets it to a recorded timestamp, none is reached while a
* session is in progress, so duration_ns is 0. 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_unit_ratio_tracks_wall_clock_from_virtual_anchor);
RUN_TEST(test_xce_core_now_ratio_above_one_scales_elapsed_up);
RUN_TEST(test_xce_core_now_ratio_below_one_scales_elapsed_down);
RUN_TEST(test_xce_sched_core_init_seeds_normal_mode_defaults);
RUN_TEST(test_xce_core_set_wallclock_anchor_seeds_real_epoch_time);
RUN_TEST(test_xce_core_set_wallclock_anchor_null_core_is_a_safe_noop);
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();
}
Reference in a new issue View git blame Copy permalink