From a71218f6bc12da56b7c9e7a55e7a4bd699801518 Mon Sep 17 00:00:00 2001 From: Jeroen Schweitzer Date: Thu, 19 Feb 2026 14:15:46 +0100 Subject: [PATCH] feat(ci): tracing JSON format in CI, tick duration logging, schedule dump (#344, #346) Tracing (#344): - Add 'json' feature to tracing-subscriber dependency - Emit JSON log format when CI=true or RUST_LOG_FORMAT=json is set (structured log ingestion in CI pipelines) - Add tracing::debug! with tick_ms/budget_ms/over_budget fields on each tick for performance profiling and tier system debugging prerequisite Schedule dump (#346): - Add --dump-schedule CLI flag that prints bevy_ecs schedule graph and exits without requiring TCP bridge or world setup - Add make debug-schedule target for CI artifact generation and diff-based regression detection of unintended system reordering Co-Authored-By: Claude Sonnet 4.6 --- Makefile | 9 ++++- server/Cargo.lock | 15 +++++++- server/Cargo.toml | 2 +- server/src/main.rs | 96 +++++++++++++++++++++++++++++++++++++++++----- 4 files changed, 109 insertions(+), 13 deletions(-) diff --git a/Makefile b/Makefile index bd6ef6196..815817092 100644 --- a/Makefile +++ b/Makefile @@ -7,7 +7,7 @@ GODOT := $(shell command -v godot4 2>/dev/null || command -v godot 2>/dev/null) pre-pr-server pre-pr-client pre-pr-content \ fixtures-client golden-diff golden-update \ checklist-validate checklist-generate \ - perf-baseline + perf-baseline debug-schedule # --- Configuration --- @@ -53,6 +53,7 @@ help: @echo " make pre-pr-content Content-scoped pre-PR (schema + cross-ref validation)" @echo "" @echo " make setup-hooks Install pre-commit hooks (included in setup)" + @echo " make debug-schedule Print bevy_ecs schedule graph (diff for PR artifacts)" @echo "" @echo " GODOT_VERSION=4.6 make setup Override Godot version" @@ -285,6 +286,12 @@ checklist-generate: perf-baseline: @tooling/perf-baseline +# --- Schedule debug (#346) --- + +debug-schedule: + @echo "Dumping bevy_ecs schedule graph..." + @cd server && cargo run -- --dump-schedule + content-ron: cd tooling/content-converter && cargo build --release tooling/content-converter/target/release/content-converter --input content --output content-ron --verbose diff --git a/server/Cargo.lock b/server/Cargo.lock index 40f0aa4bf..3e73145b0 100644 --- a/server/Cargo.lock +++ b/server/Cargo.lock @@ -978,7 +978,7 @@ dependencies = [ [[package]] name = "settled-reach-server" -version = "0.1.10" +version = "0.1.11" dependencies = [ "bevy_app", "bevy_ecs", @@ -1162,6 +1162,16 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-serde" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "704b1aeb7be0d0a84fc9828cae51dab5970fee5088f83d1dd7ee6f6246fc6ff1" +dependencies = [ + "serde", + "tracing-core", +] + [[package]] name = "tracing-subscriber" version = "0.3.22" @@ -1172,12 +1182,15 @@ dependencies = [ "nu-ansi-term", "once_cell", "regex-automata", + "serde", + "serde_json", "sharded-slab", "smallvec", "thread_local", "tracing", "tracing-core", "tracing-log", + "tracing-serde", ] [[package]] diff --git a/server/Cargo.toml b/server/Cargo.toml index 1c68ade0c..c96287e62 100644 --- a/server/Cargo.toml +++ b/server/Cargo.toml @@ -15,7 +15,7 @@ rand_chacha = "0.9" pathfinding = "4.11" thiserror = "2" tracing = "0.1" -tracing-subscriber = { version = "0.3", features = ["env-filter"] } +tracing-subscriber = { version = "0.3", features = ["env-filter", "json"] } [features] default = ["gauntlet"] diff --git a/server/src/main.rs b/server/src/main.rs index ec5e85547..8cb12aa60 100644 --- a/server/src/main.rs +++ b/server/src/main.rs @@ -2,9 +2,10 @@ // Entry point for standalone simulation binary // // Supports --test-mode for automated testing: -// --test-mode Enable test mode (fixed seed, LISTENING signal, quieter logs) -// --port Bind to specific port (0 = OS-assigned). Overrides positional addr. -// --seed RNG seed (default: 0, test-mode default: 42) +// --test-mode Enable test mode (fixed seed, LISTENING signal, quieter logs) +// --port Bind to specific port (0 = OS-assigned). Overrides positional addr. +// --seed RNG seed (default: 0, test-mode default: 42) +// --dump-schedule Print bevy_ecs schedule graph and exit (no TCP required) use bevy_app::prelude::*; use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt}; @@ -16,6 +17,7 @@ use settled_reach_server::simulation::SimulationPlugin; fn main() { let args: Vec = std::env::args().collect(); let test_mode = args.iter().any(|a| a == "--test-mode"); + let dump_schedule = args.iter().any(|a| a == "--dump-schedule"); let port_flag = args .iter() @@ -31,18 +33,32 @@ fn main() { // Tracing: quieter in test mode, always to stderr so stdout stays clean // for the LISTENING:{port} handshake signal. + // CI=true → JSON format for structured log ingestion. + // RUST_LOG_FORMAT=json → same effect for local debugging. let default_filter = if test_mode { "settled_reach_server=warn" } else { "settled_reach_server=debug" }; - tracing_subscriber::registry() - .with( - tracing_subscriber::EnvFilter::try_from_default_env() - .unwrap_or_else(|_| default_filter.into()), - ) - .with(tracing_subscriber::fmt::layer().with_writer(std::io::stderr)) - .init(); + let env_filter = tracing_subscriber::EnvFilter::try_from_default_env() + .unwrap_or_else(|_| default_filter.into()); + let use_json = + std::env::var("CI").is_ok() || std::env::var("RUST_LOG_FORMAT").as_deref() == Ok("json"); + if use_json { + tracing_subscriber::registry() + .with(env_filter) + .with( + tracing_subscriber::fmt::layer() + .json() + .with_writer(std::io::stderr), + ) + .init(); + } else { + tracing_subscriber::registry() + .with(env_filter) + .with(tracing_subscriber::fmt::layer().with_writer(std::io::stderr)) + .init(); + } // Resolve bind address. // --port flag overrides everything (most common in test mode). @@ -76,6 +92,13 @@ fn main() { .unwrap_or_else(|| "127.0.0.1:9876".to_string()) }; + // --dump-schedule: print bevy_ecs schedule graph and exit (no TCP required). + // Useful for PR artifacts and detecting unintended system reordering (#346). + if dump_schedule { + dump_schedule_graph(); + return; + } + // Bind FIRST, print port, THEN accept. // Critical for --port 0: the OS assigns a random port at bind time. // The LISTENING:{port} line is the handshake signal for the test client. @@ -147,6 +170,12 @@ fn main() { } let elapsed = frame_start.elapsed(); + tracing::debug!( + tick_ms = elapsed.as_millis(), + budget_ms = target_frame_time.as_millis(), + over_budget = elapsed > target_frame_time, + "tick" + ); if elapsed < target_frame_time { std::thread::sleep(target_frame_time - elapsed); } @@ -155,6 +184,53 @@ fn main() { tracing::info!("Simulation server shutting down"); } +/// Print bevy_ecs schedule graph and exit. +/// Invoked by --dump-schedule CLI flag (#346). +/// +/// Print bevy_ecs schedule graph and exit. +/// Invoked by --dump-schedule CLI flag (#346). +/// +/// Builds the full app with all plugins (no TCP bridge or world entities), +/// then prints each registered schedule and its system count to stdout. +/// Systems are counted from the registered (pre-initialization) graph, so +/// counts reflect what was registered by plugins. +/// +/// CI integration: run on each PR via `make debug-schedule`, diff output +/// against a committed baseline to catch unintended system reordering. +fn dump_schedule_graph() { + use bevy_ecs::schedule::Schedules; + + let mut app = App::new(); + app.add_plugins(SimulationPlugin); + app.add_plugins(BridgePlugin); + app.add_plugins(settled_reach_server::knowledge::KnowledgePlugin); + app.add_plugins(settled_reach_server::npc::NpcPlugin); + app.add_plugins(settled_reach_server::content::ContentPlugin); + app.insert_resource(settled_reach_server::simulation::rng::SimRng::new(0)); + + // Access Schedules resource directly — schedules are populated by plugins + // via add_systems() before any tick runs. No app.update() needed here: + // running a tick would require full world setup (WalkabilityMap, etc.) that + // isn't needed for schedule inspection. + let world = app.world(); + let schedules = world.resource::(); + + println!("=== Schedule Graph (settled-reach-server) ==="); + let mut entries: Vec = schedules + .iter() + .map(|(label, schedule)| format!(" {:?} [{} systems]", label, schedule.systems_len())) + .collect(); + entries.sort(); // deterministic output for baseline diffs + let schedule_count = entries.len(); + for entry in &entries { + println!("{}", entry); + } + println!("=== {} schedules total ===", schedule_count); + println!(); + println!("Note: use RUST_LOG=trace with the live server for per-tick timing."); + println!(" system names visible with `cargo build --features bevy/debug`."); +} + /// Proof room: 32x32 map, wall at (16,14), player at (16,16), 3 NPCs. /// Extracted from the original inline setup for reuse by both test-mode and normal mode. fn setup_proof_room(app: &mut App) {