feat(scheduler): show event time/session in sim echo, total sessions on replay load
repl_print_event_summary() (interactive REPL event echo) now prefixes each echoed event with "[sim] t=<ns> (<human>) session=<N>", using the same xce_core_now()/repl_format_ts_human()/session_count sources "info session" already reports. Uses session_count+1, not the raw count: events stream in and are echoed individually before the ReplaySession/ begin_round message that increments session_count is even read (file order is event, event, ..., ReplaySession), so an echoed event always belongs to the session about to begin. Add sim_prescan_session_count() (sim.c): scans the replay file from the current position via shape-only classification (mirroring sim_loop.c's own ReplayEvent/ReplaySession/SnapshotEntry dispatch), counts ReplaySession messages, then rewinds via fseek back to the exact ftell() position -- same rewind technique sim_locate_and_load_snapshot() already uses. Wired into sched_sim_driver_start(): prints "[sim] replay file contains N sessions" once at load, non-fatal on scan failure. Add test_replay_load_reports_total_session_count; extend test_step_echoes_events_before_session_decisions with t=/session=1 assertions. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
This commit is contained in:
parent
4e3e6332c5
commit
8abab049f4
4 changed files with 221 additions and 3 deletions
|
|
@ -2520,3 +2520,39 @@
|
|||
| 21:10 | Session end: 9 writes across 4 files (test_group.c, group.c, test_apply_committed_entry.c, persist.c) | 23 reads | ~127583 tok |
|
||||
| 21:11 | Session end: 9 writes across 4 files (test_group.c, group.c, test_apply_committed_entry.c, persist.c) | 23 reads | ~127583 tok |
|
||||
| 21:12 | Fixed StartTime/FinishTime never set (raft-apply-decoupling apply-pump gap) — wal_type-keyed time(NULL) stamping in apply_committed_entry, TDD RED->GREEN, bug-1561 re-observed (6th time, unrelated overlayfs artifact, not a regression) | src/controller/persist.c, src/controller/testsuite/test_apply_committed_entry.c, .wolf/buglog.json | GREEN, 1107 Tests 2 pre-existing-unrelated Failures | ~35000 |
|
||||
| 21:25 | Session end: 9 writes across 4 files (test_group.c, group.c, test_apply_committed_entry.c, persist.c) | 23 reads | ~127583 tok |
|
||||
| 23:48 | Session end: 9 writes across 4 files (test_group.c, group.c, test_apply_committed_entry.c, persist.c) | 23 reads | ~127583 tok |
|
||||
| 06:49 | Rebuilt scheduler debug profile (src/build.dbg) via xce-build.sh to deploy bug-1600 fix (group.c makeGroup rtti free) for pc13v crash-loop; ran meson test --suite scheduler | src/build.dbg/scheduler/xce_scheduler | build OK, 42 Ok / 1 Fail (bug-1560 pre-existing, unrelated) | ~15000 |
|
||||
| 23:50 | Session end: 9 writes across 4 files (test_group.c, group.c, test_apply_committed_entry.c, persist.c) | 24 reads | ~127583 tok |
|
||||
| 23:58 | Session end: 9 writes across 4 files (test_group.c, group.c, test_apply_committed_entry.c, persist.c) | 24 reads | ~127583 tok |
|
||||
| 00:00 | Session end: 9 writes across 4 files (test_group.c, group.c, test_apply_committed_entry.c, persist.c) | 24 reads | ~127583 tok |
|
||||
| 00:02 | Created .kiro/specs/build-time-versioning/spec.json | — | ~130 |
|
||||
| 00:02 | Created .kiro/specs/build-time-versioning/requirements.md | — | ~361 |
|
||||
| 00:04 | Created .kiro/specs/build-time-versioning/requirements.md | — | ~1792 |
|
||||
| 00:04 | Edited .kiro/specs/build-time-versioning/spec.json | 8→8 lines | ~55 |
|
||||
| 00:06 | Session end: 13 writes across 6 files (test_group.c, group.c, test_apply_committed_entry.c, persist.c, spec.json) | 36 reads | ~143885 tok |
|
||||
| 00:18 | Edited src/scheduler/src/repl_info.c | added 3 condition(s) | ~839 |
|
||||
| 00:18 | Edited src/scheduler/src/repl_info.c | pool() → index() | ~311 |
|
||||
| 00:18 | Edited src/scheduler/src/repl_info.c | 15→18 lines | ~300 |
|
||||
| 00:19 | Edited src/scheduler/src/repl_info.c | added 2 condition(s) | ~800 |
|
||||
| 00:20 | Edited src/scheduler/testsuite/test_repl_breakpoints_inspection.c | 8→9 lines | ~151 |
|
||||
| 00:20 | Edited src/scheduler/testsuite/test_repl_breakpoints_inspection.c | 2→3 lines | ~46 |
|
||||
| 00:20 | Edited src/scheduler/testsuite/test_repl_breakpoints_inspection.c | 2→2 lines | ~36 |
|
||||
| 00:22 | Edited src/scheduler/testsuite/test_repl_breakpoints_inspection.c | modified requirement() | ~687 |
|
||||
| 00:22 | Edited src/scheduler/testsuite/test_repl_breakpoints_inspection.c | modified requirement() | ~719 |
|
||||
| 00:23 | Edited src/scheduler/testsuite/test_repl_breakpoints_inspection.c | 4→6 lines | ~105 |
|
||||
| 07:27 | Fixed info resource/info worker to gate value+used display on XCE_RESF_CONSUMABLE, added ordtype to resource definition | src/scheduler/src/repl_info.c, src/scheduler/testsuite/test_repl_breakpoints_inspection.c, .wolf/buglog.json | GREEN, 42/43 Ok, only pre-existing bug-1560 remains | ~90000 |
|
||||
| 00:29 | Edited src/scheduler/src/repl_break.c | modified 5() | ~460 |
|
||||
| 00:29 | Edited src/scheduler/src/repl_break.c | inline fix | ~11 |
|
||||
| 00:30 | Edited src/scheduler/testsuite/test_repl_breakpoints_inspection.c | expanded (+19 lines) | ~511 |
|
||||
| 00:33 | Session end: 26 writes across 9 files (test_group.c, group.c, test_apply_committed_entry.c, persist.c, spec.json) | 52 reads | ~204795 tok |
|
||||
| 00:36 | Edited src/scheduler/src/repl_break.c | 10→13 lines | ~230 |
|
||||
| 00:36 | Edited src/scheduler/src/repl_break.c | 3→3 lines | ~53 |
|
||||
| 00:39 | Edited src/scheduler/src/sim.c | added 7 condition(s) | ~845 |
|
||||
| 00:39 | Edited src/scheduler/src/sim.c | added 1 condition(s) | ~230 |
|
||||
| 00:42 | Edited src/scheduler/testsuite/test_repl_breakpoints_inspection.c | modified requirement() | ~458 |
|
||||
| 00:42 | Edited src/scheduler/testsuite/test_repl_breakpoints_inspection.c | 3→4 lines | ~40 |
|
||||
| 00:43 | Session end: 32 writes across 10 files (test_group.c, group.c, test_apply_committed_entry.c, persist.c, spec.json) | 55 reads | ~220167 tok |
|
||||
| 07:46 | ASAN build+full testsuite verified for repl_break.c/sim.c session-count changes | src/scheduler/src/repl_break.c, src/scheduler/src/sim.c, src/scheduler/testsuite/test_repl_breakpoints_inspection.c | 42/43 Ok, only known bug-1560 admin_request symlink failure; new+changed tests all PASS | ~55k |
|
||||
| 00:48 | Created ../../../../../../tmp/claude-1000/-home-rshen-projects-xce-worktrees-scheduler-framework/0334ebbe-8d9c-4931-871d-87c678f83a79/scratchpad/log_bug_1602.py | — | ~1054 |
|
||||
| 08:31 | Added event time/session echo (session_count+1, events precede their own BEGIN_ROUND marker) and replay-file session-count pre-scan (ftell/fseek, shape-only) | src/scheduler/src/repl_break.c, src/scheduler/src/sim.c, src/scheduler/testsuite/test_repl_breakpoints_inspection.c, .wolf/buglog.json | GREEN, 42/43 Ok, only pre-existing bug-1560 remains | ~110000 |
|
||||
|
|
|
|||
|
|
@ -569,10 +569,31 @@ bool repl_cmd_delete(xce_sched_sim_driver_t* sim, const char* line)
|
|||
* sim_loop.c), leaving every input event silent unless a breakpoint
|
||||
* happened to match it. Only ever called from xce_repl_on_event() below,
|
||||
* itself only reached when sim->interactive (repl.h's own gate) -- zero
|
||||
* output added to batch `--sim` mode.
|
||||
* output added to batch `--sim` mode. Prefixed with a "[sim] t=... (...)
|
||||
* session=..." line (same xce_core_now()/repl_format_ts_human()/
|
||||
* rs->session_count sources `info session`/`info config`, repl_info.c,
|
||||
* already use) so an operator reading a step/continue transcript can tell
|
||||
* WHEN each event happened and which session it belongs to, not just what
|
||||
* happened. Uses session_count+1, NOT the raw count: sim_loop.c's replay
|
||||
* reader calls xce_repl_check_event() (-> here) for every raw event AS IT
|
||||
* STREAMS IN, and only reads that batch's own ReplaySession/begin_round
|
||||
* message (which is what increments session_count, xce_repl_on_begin_round)
|
||||
* AFTER all of that session's events -- file order is event, event, ...,
|
||||
* ReplaySession. So every event echoed here always belongs to the session
|
||||
* about to begin, never one already counted.
|
||||
*/
|
||||
static void repl_print_event_summary(const xce_core_event_t* ev)
|
||||
static void repl_print_event_summary(xce_sched_sim_driver_t* sim,
|
||||
const xce_core_event_t* ev)
|
||||
{
|
||||
xce_sched_repl_state_t* rs = sim->repl_state;
|
||||
char ts_human[32];
|
||||
|
||||
repl_format_ts_human(xce_core_now(&(sim->core)), ts_human,
|
||||
sizeof(ts_human));
|
||||
fprintf(stdout, "[sim] t=%llu (%s) session=%llu\n",
|
||||
(unsigned long long)xce_core_now(&(sim->core)), ts_human,
|
||||
(unsigned long long)((rs != NULL) ? rs->session_count + 1 : 1));
|
||||
|
||||
switch (ev->type) {
|
||||
case XCE_CORE_EVENT_CONFIG_PUSH:
|
||||
fprintf(stdout, "[sim] event: CONFIG_PUSH\n");
|
||||
|
|
@ -699,7 +720,7 @@ void xce_repl_on_event(xce_sched_sim_driver_t* sim, xce_core_event_t* ev)
|
|||
/* task 12.5, bug-1595: unconditional echo, printed before the
|
||||
* breakpoint check below so the operator sees "event happened" before
|
||||
* (if it also matches) "breakpoint hit". */
|
||||
repl_print_event_summary(ev);
|
||||
repl_print_event_summary(sim, ev);
|
||||
|
||||
bp = repl_find_event_breakpoint(rs, ev);
|
||||
if (bp != NULL) {
|
||||
|
|
|
|||
|
|
@ -327,6 +327,87 @@ static void sim_set_virtual_clock(xce_sched_sim_driver_t* sim,
|
|||
sim->sim_speed_den = 1;
|
||||
}
|
||||
|
||||
/*
|
||||
* sim_prescan_session_count - counts the total number of ReplaySession
|
||||
* (BEGIN_ROUND) messages remaining in sim->replay_file from the current
|
||||
* position onward, then rewinds the file back to that exact position, so
|
||||
* sched_sim_driver_start() can report "this replay file has N sessions" up
|
||||
* front, before sched_sim_driver_run()'s real event loop (sim_loop.c)
|
||||
* starts consuming the same stream. Uses the identical shape-only
|
||||
* classification (msg_root_has_shape()) sim_loop.c's own main loop uses to
|
||||
* tell ReplayEvent/ReplaySession/SnapshotEntry messages apart, and the same
|
||||
* ftell()/fseek() rewind technique sim_locate_and_load_snapshot() above
|
||||
* already establishes -- safe because this codebase's capn_init_fp() calls
|
||||
* are always unpacked (packed=0), which reads via a single plain fread()
|
||||
* per message with no internal read-ahead buffer (msg_root_has_shape()'s
|
||||
* own file header comment), so ftell()/fseek() stay exactly in sync with
|
||||
* message boundaries. Never decodes a message's fields, only its wire
|
||||
* shape -- counting needs nothing more. Scope: only sim->replay_file's own
|
||||
* session count is reported -- a run under --sim-alt-events substitutes a
|
||||
* DIFFERENT event stream at run time (sim_loop.c), which this scan does
|
||||
* not see; a niche enough case that reporting the primary file's own count
|
||||
* is still the right default.
|
||||
*/
|
||||
static int sim_prescan_session_count(xce_sched_sim_driver_t* sim,
|
||||
uint64_t* out_count)
|
||||
{
|
||||
FILE* f;
|
||||
long resume_at;
|
||||
uint64_t count = 0;
|
||||
|
||||
if ((sim == NULL) || (sim->replay_file == NULL) || (out_count == NULL)) {
|
||||
return -EINVAL;
|
||||
}
|
||||
|
||||
f = sim->replay_file;
|
||||
resume_at = ftell(f);
|
||||
if (resume_at < 0) {
|
||||
return -errno;
|
||||
}
|
||||
|
||||
for (;;) {
|
||||
struct capn c;
|
||||
capn_ptr root;
|
||||
|
||||
if (capn_init_fp(&c, f, 0) != 0) {
|
||||
break; /* end of file (or malformed trailing data) -- same
|
||||
* "nonzero means no more messages" convention every
|
||||
* other reader in this file follows. */
|
||||
}
|
||||
|
||||
if (msg_root_has_shape(&c, &root, ReplaySession_word_count,
|
||||
ReplaySession_pointer_count)) {
|
||||
count++;
|
||||
capn_free(&c);
|
||||
continue;
|
||||
}
|
||||
|
||||
if (msg_root_has_shape(&c, &root, ReplayEvent_word_count,
|
||||
ReplayEvent_pointer_count)) {
|
||||
capn_free(&c);
|
||||
continue;
|
||||
}
|
||||
|
||||
if (msg_root_has_shape(&c, &root, SnapshotEntry_word_count,
|
||||
SnapshotEntry_pointer_count)) {
|
||||
capn_free(&c); /* mid-replay checkpoint -- skip, don't stop */
|
||||
continue;
|
||||
}
|
||||
|
||||
/* Unrecognized shape -- end of the message stream, same stop
|
||||
* condition sim_loop.c's own main loop uses. */
|
||||
capn_free(&c);
|
||||
break;
|
||||
}
|
||||
|
||||
if (fseek(f, resume_at, SEEK_SET) != 0) {
|
||||
return -errno;
|
||||
}
|
||||
|
||||
*out_count = count;
|
||||
return 0;
|
||||
}
|
||||
|
||||
int sched_sim_driver_start(xce_sched_sim_driver_t* sim,
|
||||
const sched_sim_args_t* args)
|
||||
{
|
||||
|
|
@ -393,6 +474,22 @@ int sched_sim_driver_start(xce_sched_sim_driver_t* sim,
|
|||
|
||||
sim_set_virtual_clock(sim, snapshot_ts, args->sim_speed);
|
||||
|
||||
/* Orientation for an operator about to `step`/`continue` through this
|
||||
* file (or watch a batch --sim run go by): how many sessions are there
|
||||
* in total? Purely informational -- a scan failure (e.g. a stat error
|
||||
* on an already-open, already-validated file) is not fatal to starting
|
||||
* the simulation, so it is silently skipped rather than aborting
|
||||
* startup over a diagnostic nicety. */
|
||||
{
|
||||
uint64_t total_sessions = 0;
|
||||
|
||||
if (sim_prescan_session_count(sim, &total_sessions) == 0) {
|
||||
fprintf(stdout, "[sim] replay file contains %llu session%s\n",
|
||||
(unsigned long long)total_sessions,
|
||||
(total_sessions == 1) ? "" : "s");
|
||||
}
|
||||
}
|
||||
|
||||
/* Req 5 AC 3 (design review follow-up, 2026-08-19): activate the
|
||||
* virtualized clock for tlog logging now that it's seeded -- every
|
||||
* ERROR/WARN/INFO/TRACE line emitted for the rest of this run shows
|
||||
|
|
|
|||
|
|
@ -1779,11 +1779,74 @@ static void test_step_echoes_events_before_session_decisions(void)
|
|||
"events must be echoed BEFORE the session's "
|
||||
"resulting decision (bug-1595)");
|
||||
|
||||
{
|
||||
char* ts_line_pos = strstr(captured, "[sim] t=");
|
||||
|
||||
TEST_ASSERT_NOT_NULL_MESSAGE(
|
||||
ts_line_pos,
|
||||
"each echoed event must be preceded by a t=.../session=... "
|
||||
"line so an operator can tell when/which session it happened "
|
||||
"in");
|
||||
TEST_ASSERT_TRUE_MESSAGE(
|
||||
ts_line_pos < jobpush_pos,
|
||||
"the t=.../session=... line must precede the event it "
|
||||
"describes");
|
||||
TEST_ASSERT_NOT_NULL_MESSAGE(
|
||||
strstr(captured, "session=1"),
|
||||
"the first (and only) session's events must be tagged "
|
||||
"session=1 -- xce_repl_on_begin_round() increments "
|
||||
"session_count before this session's event batch is pushed");
|
||||
}
|
||||
|
||||
free(captured);
|
||||
|
||||
printf("test_step_echoes_events_before_session_decisions: PASS\n");
|
||||
}
|
||||
|
||||
/*
|
||||
* New requirement (2026-08-20): loading a replay file reports its total
|
||||
* session count up front (sim.c's sched_sim_driver_start(), via
|
||||
* sim_prescan_session_count()'s ftell/fseek pre-scan), so an operator knows
|
||||
* how many `step`s exist before starting to walk through them.
|
||||
*/
|
||||
static void test_replay_load_reports_total_session_count(void)
|
||||
{
|
||||
char replay_path[PATH_MAX];
|
||||
char aux_dir[PATH_MAX];
|
||||
char script_path[PATH_MAX];
|
||||
char capture_path[PATH_MAX];
|
||||
FILE* f;
|
||||
char* captured;
|
||||
|
||||
f = write_header_and_snapshot(replay_path, sizeof(replay_path),
|
||||
"_sessioncount");
|
||||
TEST_ASSERT_NOT_NULL(f);
|
||||
|
||||
append_jobs_push_event(f, 1000ULL, 8181ULL, "normal");
|
||||
append_replay_session(f, 1500ULL);
|
||||
append_jobs_push_event(f, 2000ULL, 8182ULL, "normal");
|
||||
append_replay_session(f, 2500ULL);
|
||||
append_end_of_stream_marker(f);
|
||||
fclose(f);
|
||||
|
||||
make_tmp_dir(aux_dir, sizeof(aux_dir), "_sessioncountaux");
|
||||
snprintf(script_path, sizeof(script_path), "%s/script.txt", aux_dir);
|
||||
snprintf(capture_path, sizeof(capture_path), "%s/capture.out", aux_dir);
|
||||
write_text_file(script_path, "quit\n");
|
||||
|
||||
captured = run_group_d_and_capture(replay_path, script_path,
|
||||
capture_path);
|
||||
|
||||
TEST_ASSERT_NOT_NULL_MESSAGE(
|
||||
strstr(captured, "[sim] replay file contains 2 sessions"),
|
||||
"loading a 2-session replay file must report the total session "
|
||||
"count up front, before any step/continue command runs");
|
||||
|
||||
free(captured);
|
||||
|
||||
printf("test_replay_load_reports_total_session_count: PASS\n");
|
||||
}
|
||||
|
||||
int main(void)
|
||||
{
|
||||
UNITY_BEGIN();
|
||||
|
|
@ -1818,6 +1881,7 @@ int main(void)
|
|||
RUN_TEST(test_event_breakpoint_pauses_repl_at_matching_event);
|
||||
RUN_TEST(test_decision_breakpoint_pauses_after_decision_output);
|
||||
RUN_TEST(test_step_echoes_events_before_session_decisions);
|
||||
RUN_TEST(test_replay_load_reports_total_session_count);
|
||||
|
||||
return UNITY_END();
|
||||
}
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue