[INFO] fetching crate ramu_rs 0.1.1... [INFO] testing ramu_rs-0.1.1 against 1.95.0 for beta-1.96-3 [INFO] extracting crate ramu_rs 0.1.1 into /workspace/builds/worker-0-tc1/source [INFO] started tweaking crates.io crate ramu_rs 0.1.1 [INFO] finished tweaking crates.io crate ramu_rs 0.1.1 [INFO] tweaked toml for crates.io crate ramu_rs 0.1.1 written to /workspace/builds/worker-0-tc1/source/Cargo.toml [INFO] validating manifest of crates.io crate ramu_rs 0.1.1 on toolchain 1.95.0 [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.95.0" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }` [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.95.0" "generate-lockfile" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] [stderr] Blocking waiting for file lock on package cache [INFO] [stderr] Updating crates.io index [INFO] [stderr] Blocking waiting for file lock on package cache [INFO] [stderr] Locking 62 packages to latest compatible versions [INFO] [stderr] Adding enum-as-inner v0.5.1 (available: v0.7.0) [INFO] [stderr] Adding num_enum v0.5.11 (available: v0.7.6) [INFO] [stderr] Adding toml v0.5.11 (available: v1.1.2+spec-1.1.0) [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.95.0" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] [stderr] Blocking waiting for file lock on package cache [INFO] [stderr] Blocking waiting for file lock on package cache [INFO] [stderr] Downloading crates ... [INFO] [stderr] Downloaded enum-as-inner v0.5.1 [INFO] [stderr] Downloaded scratch v1.0.9 [INFO] [stderr] Downloaded cxxbridge-flags v1.0.194 [INFO] [stderr] Downloaded link-cplusplus v1.0.12 [INFO] [stderr] Downloaded cxxbridge-macro v1.0.194 [INFO] [stderr] Downloaded cxx-build v1.0.194 [INFO] [stderr] Downloaded cxxbridge-cmd v1.0.194 [INFO] [stderr] Downloaded tracing-subscriber v0.3.23 [INFO] [stderr] Downloaded cxx v1.0.194 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+1.95.0" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }` [INFO] [stdout] 061a806778a014a0472dbb17f295fc5462647a5309d09159683187e69b4f6ae9 [INFO] running `Command { std: "docker" "start" "-a" "061a806778a014a0472dbb17f295fc5462647a5309d09159683187e69b4f6ae9", kill_on_drop: false }` [INFO] running `Command { std: "docker" "inspect" "061a806778a014a0472dbb17f295fc5462647a5309d09159683187e69b4f6ae9", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "061a806778a014a0472dbb17f295fc5462647a5309d09159683187e69b4f6ae9", kill_on_drop: false }` [INFO] [stdout] 061a806778a014a0472dbb17f295fc5462647a5309d09159683187e69b4f6ae9 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+1.95.0" "build" "--frozen" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 9e6b469cd3fa9a19f7d6f66210a6e7779b3ea2096010b9229255d16bc44ec37f [INFO] running `Command { std: "docker" "start" "-a" "9e6b469cd3fa9a19f7d6f66210a6e7779b3ea2096010b9229255d16bc44ec37f", kill_on_drop: false }` [INFO] [stderr] Compiling proc-macro2 v1.0.106 [INFO] [stderr] Compiling quote v1.0.45 [INFO] [stderr] Compiling unicode-ident v1.0.24 [INFO] [stderr] Compiling once_cell v1.21.4 [INFO] [stderr] Compiling shlex v1.3.0 [INFO] [stderr] Compiling find-msvc-tools v0.1.9 [INFO] [stderr] Compiling equivalent v1.0.2 [INFO] [stderr] Compiling hashbrown v0.17.0 [INFO] [stderr] Compiling syn v1.0.109 [INFO] [stderr] Compiling toml_datetime v0.6.11 [INFO] [stderr] Compiling serde_core v1.0.228 [INFO] [stderr] Compiling winnow v0.5.40 [INFO] [stderr] Compiling tracing-core v0.1.36 [INFO] [stderr] Compiling cc v1.2.61 [INFO] [stderr] Compiling cxxbridge-flags v1.0.194 [INFO] [stderr] Compiling regex-syntax v0.8.10 [INFO] [stderr] Compiling serde v1.0.228 [INFO] [stderr] Compiling pin-project-lite v0.2.17 [INFO] [stderr] Compiling log v0.4.29 [INFO] [stderr] Compiling lazy_static v1.5.0 [INFO] [stderr] Compiling cfg-if v1.0.4 [INFO] [stderr] Compiling indexmap v2.14.0 [INFO] [stderr] Compiling tracing-log v0.2.0 [INFO] [stderr] Compiling thread_local v1.1.9 [INFO] [stderr] Compiling sharded-slab v0.1.7 [INFO] [stderr] Compiling syn v2.0.117 [INFO] [stderr] Compiling smallvec v1.15.1 [INFO] [stderr] Compiling regex-automata v0.4.14 [INFO] [stderr] Compiling link-cplusplus v1.0.12 [INFO] [stderr] Compiling cxx v1.0.194 [INFO] [stderr] Compiling heck v0.4.1 [INFO] [stderr] Compiling nu-ansi-term v0.50.3 [INFO] [stderr] Compiling toml_edit v0.19.15 [INFO] [stderr] Compiling foldhash v0.2.0 [INFO] [stderr] Compiling enum-as-inner v0.5.1 [INFO] [stderr] Compiling matchers v0.2.0 [INFO] [stderr] Compiling proc-macro-crate v1.3.1 [INFO] [stderr] Compiling num_enum_derive v0.5.11 [INFO] [stderr] Compiling num_enum v0.5.11 [INFO] [stderr] Compiling serde_derive v1.0.228 [INFO] [stderr] Compiling tracing-attributes v0.1.31 [INFO] [stderr] Compiling cxxbridge-macro v1.0.194 [INFO] [stderr] Compiling tracing v0.1.44 [INFO] [stderr] Compiling tracing-subscriber v0.3.23 [INFO] [stderr] Compiling toml v0.5.11 [INFO] [stderr] Compiling ramu_rs v0.1.1 (/opt/rustwide/workdir) [INFO] [stderr] Finished `dev` profile [unoptimized + debuginfo] target(s) in 54.58s [INFO] running `Command { std: "docker" "inspect" "9e6b469cd3fa9a19f7d6f66210a6e7779b3ea2096010b9229255d16bc44ec37f", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "9e6b469cd3fa9a19f7d6f66210a6e7779b3ea2096010b9229255d16bc44ec37f", kill_on_drop: false }` [INFO] [stdout] 9e6b469cd3fa9a19f7d6f66210a6e7779b3ea2096010b9229255d16bc44ec37f [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+1.95.0" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 13a92aa32d09b71781bd22c705d3ef7b917cb4a0d458f97df99b1ee66d8648b0 [INFO] running `Command { std: "docker" "start" "-a" "13a92aa32d09b71781bd22c705d3ef7b917cb4a0d458f97df99b1ee66d8648b0", kill_on_drop: false }` [INFO] [stderr] Compiling ramu_rs v0.1.1 (/opt/rustwide/workdir) [INFO] [stderr] Finished `test` profile [unoptimized + debuginfo] target(s) in 2.53s [INFO] running `Command { std: "docker" "inspect" "13a92aa32d09b71781bd22c705d3ef7b917cb4a0d458f97df99b1ee66d8648b0", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "13a92aa32d09b71781bd22c705d3ef7b917cb4a0d458f97df99b1ee66d8648b0", kill_on_drop: false }` [INFO] [stdout] 13a92aa32d09b71781bd22c705d3ef7b917cb4a0d458f97df99b1ee66d8648b0 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-0-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+1.95.0" "test" "--frozen", kill_on_drop: false }` [INFO] [stdout] 1d65627f326fe7067646176246534396beb8a0d6d40e5f346d289dbb6ec3d74a [INFO] running `Command { std: "docker" "start" "-a" "1d65627f326fe7067646176246534396beb8a0d6d40e5f346d289dbb6ec3d74a", kill_on_drop: false }` [INFO] [stderr] Finished `test` profile [unoptimized + debuginfo] target(s) in 0.10s [INFO] [stderr] Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/ramu_rs-ce4d82e5a3049ae4) [INFO] [stdout] [INFO] [stdout] running 8 tests [INFO] [stdout] test config::tests::dum_config ... ignored [INFO] [stdout] 2026-04-29T14:20:40.661338Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2026-04-29T14:20:40.661387Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2026-04-29T14:20:40.661405Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2026-04-29T14:20:40.661417Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 } [INFO] [stdout] 2026-04-29T14:20:40.661471Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661487Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661499Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661511Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661528Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661543Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661557Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661572Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661584Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661598Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661610Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661622Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661634Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661633Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2026-04-29T14:20:40.661655Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661667Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2026-04-29T14:20:40.661670Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661686Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2026-04-29T14:20:40.661688Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661700Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 } [INFO] [stdout] 2026-04-29T14:20:40.661722Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661741Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661760Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661747Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661776Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661785Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2026-04-29T14:20:40.661778Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661791Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661803Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2026-04-29T14:20:40.661805Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661810Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661818Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2026-04-29T14:20:40.661824Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661828Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661830Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 } [INFO] [stdout] 2026-04-29T14:20:40.661845Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661838Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661863Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661863Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661865Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661878Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661883Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661884Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661892Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661897Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661904Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661906Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661910Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661920Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661922Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661927Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661933Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.661954Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661963Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661969Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661981Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661983Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661988Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.661997Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662001Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662007Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662016Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662024Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662029Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662014Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662043Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662045Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662056Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662047Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662059Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662070Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662074Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662083Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662072Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662097Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662095Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662100Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662112Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662110Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662124Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662133Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662142Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662148Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662131Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662161Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662156Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662163Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662176Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662183Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662191Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662197Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662188Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662207Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662216Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662221Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662218Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662230Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662233Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662244Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662246Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662258Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662267Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662273Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662281Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662291Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662295Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662308Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662321Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662307Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662335Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662345Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662349Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] test utils::tests::test_addr ... 2026-04-29T14:20:40.662363Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] ok [INFO] [stdout] 2026-04-29T14:20:40.662379Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662359Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662393Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662401Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662407Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662414Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662421Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662434Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662427Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662240Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662481Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662521Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662537Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662556Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662571Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662605Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662619Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.662633Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662646Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662658Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662669Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662681Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662693Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662704Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662715Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662728Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662739Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662750Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662761Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662772Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662783Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662795Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662806Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662818Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662833Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662848Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662862Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662865Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2026-04-29T14:20:40.662876Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662882Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2026-04-29T14:20:40.662891Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662896Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2026-04-29T14:20:40.662905Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662907Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 } [INFO] [stdout] 2026-04-29T14:20:40.662918Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662448Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662963Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662984Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662998Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663011Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663024Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663037Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663050Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663062Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663075Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663091Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663104Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663117Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663137Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2026-04-29T14:20:40.663186Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2026-04-29T14:20:40.663201Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2026-04-29T14:20:40.663215Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2026-04-29T14:20:40.663226Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 } [INFO] [stdout] 2026-04-29T14:20:40.663247Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.663258Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663261Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.663273Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663277Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=0 [INFO] [stdout] 2026-04-29T14:20:40.663286Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663290Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.663299Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663303Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.663317Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.663316Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663329Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.663331Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663344Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.663349Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663356Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=0 [INFO] [stdout] 2026-04-29T14:20:40.663365Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663372Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=39 [INFO] [stdout] 2026-04-29T14:20:40.663378Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663391Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663389Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=55 [INFO] [stdout] 2026-04-29T14:20:40.663404Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663405Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=1 [INFO] [stdout] 2026-04-29T14:20:40.663409Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663417Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663421Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=0 [INFO] [stdout] 2026-04-29T14:20:40.663430Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663431Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663437Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=16 [INFO] [stdout] 2026-04-29T14:20:40.663444Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663452Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663454Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=16 [INFO] [stdout] 2026-04-29T14:20:40.663458Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663470Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=16 [INFO] [stdout] 2026-04-29T14:20:40.663486Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] test scheduler::tests::test ... ok [INFO] [stdout] 2026-04-29T14:20:40.663499Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=16 [INFO] [stdout] 2026-04-29T14:20:40.663504Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663519Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=55 [INFO] [stdout] 2026-04-29T14:20:40.663521Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663539Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663537Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=39 [INFO] [stdout] 2026-04-29T14:20:40.663552Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663559Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.663565Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663574Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.663588Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.663587Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663601Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.662518Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663602Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663612Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.663625Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.663619Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663621Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663638Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.663639Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663651Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.663650Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663655Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663664Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.663666Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663677Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.663687Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.663685Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663700Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.663713Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.663724Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.663729Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663737Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.663750Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.663746Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663760Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.663762Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663772Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.663785Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.663780Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663796Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.663800Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663809Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.663822Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.663816Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663833Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.663835Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663845Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.663849Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663860Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.663862Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663871Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.663876Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663883Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.663890Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663897Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.663907Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.663904Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663920Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.663927Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663933Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.663960Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.663975Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.663976Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.663989Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.663992Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.664001Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.664011Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.664008Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.664024Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.664028Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.664038Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.664044Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664048Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.664057Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664061Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.664073Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.664071Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664083Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.664085Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664096Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.664099Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664109Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.664113Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664120Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.664126Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664133Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.664140Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664146Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.664154Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664155Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.664168Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664169Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.664181Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664186Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=16 [INFO] [stdout] 2026-04-29T14:20:40.664195Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664199Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.664208Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664214Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.664222Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664227Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.664234Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664241Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.664246Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664259Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664256Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=20 [INFO] [stdout] 2026-04-29T14:20:40.664272Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664274Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=20 [INFO] [stdout] 2026-04-29T14:20:40.664286Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664292Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=20 [INFO] [stdout] 2026-04-29T14:20:40.664299Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664309Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=20 [INFO] [stdout] 2026-04-29T14:20:40.664314Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664328Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.662931Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664354Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664358Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664370Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664373Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664385Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664387Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664399Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664401Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664415Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2026-04-29T14:20:40.664413Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664427Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664439Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.664453Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2026-04-29T14:20:40.664498Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2026-04-29T14:20:40.664516Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.664528Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.664537Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2026-04-29T14:20:40.664541Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2026-04-29T14:20:40.664554Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.664557Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.664568Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.664571Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.664583Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.664586Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2026-04-29T14:20:40.664600Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.664603Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.664615Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.664618Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.664626Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2026-04-29T14:20:40.664632Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.664646Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.664643Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2026-04-29T14:20:40.664659Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.664661Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2026-04-29T14:20:40.664671Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2026-04-29T14:20:40.664678Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2026-04-29T14:20:40.664688Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2026-04-29T14:20:40.664697Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2026-04-29T14:20:40.664706Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2026-04-29T14:20:40.664714Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2026-04-29T14:20:40.664731Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2026-04-29T14:20:40.664733Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2026-04-29T14:20:40.664749Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2026-04-29T14:20:40.664753Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2026-04-29T14:20:40.664767Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2026-04-29T14:20:40.664770Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2026-04-29T14:20:40.664785Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2026-04-29T14:20:40.664786Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2026-04-29T14:20:40.664803Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2026-04-29T14:20:40.664804Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2026-04-29T14:20:40.664826Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.664821Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2026-04-29T14:20:40.664837Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.664842Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2026-04-29T14:20:40.664850Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.664863Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.664859Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2026-04-29T14:20:40.664872Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.664880Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.664884Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.664891Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.664900Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.664903Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.664912Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.664916Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.664925Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.664927Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.664326Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=26 [INFO] [stdout] 2026-04-29T14:20:40.664937Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.664978Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.663671Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.665000Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.665017Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.665009Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.665030Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.665040Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.665033Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.665052Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.665065Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.665062Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.665074Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.665088Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.665086Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.665101Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.665103Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.665112Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.665124Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.665117Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.665135Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.665143Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.665145Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.665173Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.665187Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.665193Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.665201Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.665208Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.665212Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.665221Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.665223Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.665238Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.665235Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.665248Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.665251Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.665260Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.665273Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.665270Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.665283Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.665286Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.665295Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.668986Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669000Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669011Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669019Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.669026Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669033Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.669038Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669047Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669051Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669058Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.669070Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.669064Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.669083Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669086Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.669094Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.669100Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669105Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.669113Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.669118Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669126Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.669131Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.669141Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.669145Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.669158Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669156Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.669169Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.669171Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669181Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.669184Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669195Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669197Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669205Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.669209Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669218Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.669223Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669231Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669235Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669241Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.669247Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669253Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.669260Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669267Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669273Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669277Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.669288Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669290Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.669302Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669304Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669315Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669318Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.669329Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669330Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.669342Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669345Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669355Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669358Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.669369Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669371Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.669385Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669382Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669396Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.669398Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669408Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.669411Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669421Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669424Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669432Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.669437Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669445Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.669452Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669458Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669466Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669468Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.669480Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669482Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.669493Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669496Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669509Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.669507Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669521Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.669523Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669534Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669536Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669545Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.669550Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.669557Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.669562Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2026-04-29T14:20:40.669570Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669581Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.669593Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.669606Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669615Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.669627Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.669642Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669649Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2026-04-29T14:20:40.669652Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.669665Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.669667Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.669678Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669680Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.669689Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.669694Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2026-04-29T14:20:40.669701Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.669714Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.669706Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.669725Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.669729Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.669737Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.669743Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.669751Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17 [INFO] [stdout] 2026-04-29T14:20:40.669757Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.669763Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.669771Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.669777Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.669782Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2026-04-29T14:20:40.669792Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.669799Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2026-04-29T14:20:40.669806Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.669818Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2026-04-29T14:20:40.669821Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2026-04-29T14:20:40.669835Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2026-04-29T14:20:40.669840Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2026-04-29T14:20:40.669852Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2026-04-29T14:20:40.669858Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2026-04-29T14:20:40.669870Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2026-04-29T14:20:40.669876Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2026-04-29T14:20:40.669888Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2026-04-29T14:20:40.669894Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27 [INFO] [stdout] 2026-04-29T14:20:40.669904Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2026-04-29T14:20:40.669911Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27 [INFO] [stdout] 2026-04-29T14:20:40.669921Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2026-04-29T14:20:40.669928Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26 [INFO] [stdout] 2026-04-29T14:20:40.669936Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2026-04-29T14:20:40.669962Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38 [INFO] [stdout] 2026-04-29T14:20:40.669973Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2026-04-29T14:20:40.669994Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.669990Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23 [INFO] [stdout] 2026-04-29T14:20:40.670005Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.670009Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23 [INFO] [stdout] 2026-04-29T14:20:40.670016Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.670030Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670028Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26 [INFO] [stdout] 2026-04-29T14:20:40.670040Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670052Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670065Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670055Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 } clk=17 req.finish_time=37 [INFO] [stdout] 2026-04-29T14:20:40.670075Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.670080Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.670087Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.670092Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670099Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670105Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670109Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670118Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.670121Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670129Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670133Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670141Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670143Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.670157Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.670158Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.670167Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670170Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670179Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670181Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670193Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.670194Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670204Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670206Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670216Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670219Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.670229Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.670231Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.670240Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670243Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670252Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670254Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670265Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.670266Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670275Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670279Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670288Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670290Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.670302Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.670303Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.670312Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670316Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.665166Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=26 [INFO] [stdout] 2026-04-29T14:20:40.670331Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670343Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670337Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=39 future=25 [INFO] [stdout] 2026-04-29T14:20:40.670355Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670357Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=1 future=37 [INFO] [stdout] 2026-04-29T14:20:40.670366Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.670379Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.670376Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=22 [INFO] [stdout] 2026-04-29T14:20:40.670391Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670393Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=22 [INFO] [stdout] 2026-04-29T14:20:40.670401Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670412Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670411Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=39 future=25 [INFO] [stdout] 2026-04-29T14:20:40.670424Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670435Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.670430Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 36 } clk=16 req.finish_time=36 [INFO] [stdout] 2026-04-29T14:20:40.670446Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.670459Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670468Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670479Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670491Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670503Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.670514Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.670526Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670536Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670547Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670559Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670570Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.670582Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.670594Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670604Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670616Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670629Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670639Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.670652Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.670664Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670674Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670685Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670697Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670707Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.670728Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.670740Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670750Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670762Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670774Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670784Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.670796Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.670809Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670818Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670831Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670843Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670853Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.670865Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.670877Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670897Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670909Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.670921Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670932Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.670959Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.670971Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.670980Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.670991Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671002Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671011Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.671022Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.671033Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671042Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671053Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671054Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671064Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671077Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.671078Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671088Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.671091Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671101Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=17 [INFO] [stdout] 2026-04-29T14:20:40.671104Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671112Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.671118Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671128Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.671131Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671142Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.671144Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671159Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671156Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.671170Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671173Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=21 [INFO] [stdout] 2026-04-29T14:20:40.671183Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671190Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=21 [INFO] [stdout] 2026-04-29T14:20:40.671197Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671209Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671208Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=0 future=21 [INFO] [stdout] 2026-04-29T14:20:40.671221Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671224Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=0 future=21 [INFO] [stdout] 2026-04-29T14:20:40.671235Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671241Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=0 future=36 [INFO] [stdout] 2026-04-29T14:20:40.671246Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671259Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671257Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=0 future=36 [INFO] [stdout] 2026-04-29T14:20:40.671272Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671273Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=40 future=51 [INFO] [stdout] 2026-04-29T14:20:40.671283Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671289Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=2 future=51 [INFO] [stdout] 2026-04-29T14:20:40.671296Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671305Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=23 [INFO] [stdout] 2026-04-29T14:20:40.671310Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671323Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671321Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=23 [INFO] [stdout] 2026-04-29T14:20:40.671335Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671337Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=0 future=42 [INFO] [stdout] 2026-04-29T14:20:40.671349Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671352Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=0 future=42 [INFO] [stdout] 2026-04-29T14:20:40.671360Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671368Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=40 future=51 [INFO] [stdout] 2026-04-29T14:20:40.671372Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671387Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671391Z DEBUG ramu_rs::controller: write request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 17 } [INFO] [stdout] 2026-04-29T14:20:40.671397Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671409Z DEBUG ramu_rs::test: recv req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 17 } [INFO] [stdout] 2026-04-29T14:20:40.671410Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671425Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671427Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671437Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671439Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671450Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671452Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671462Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671466Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671472Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671477Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671484Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671489Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671495Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671503Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671505Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671513Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671517Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671525Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671529Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671539Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671539Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671550Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671552Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671565Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671563Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671575Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671587Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671584Z DEBUG ramu_rs::test: recv req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 } [INFO] [stdout] 2026-04-29T14:20:40.671599Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671602Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671608Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671616Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671620Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671630Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671633Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671643Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671643Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671654Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671655Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671669Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671667Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671679Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671682Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671691Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671693Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671702Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671705Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671719Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671723Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40 [INFO] [stdout] 2026-04-29T14:20:40.671731Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671737Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.671743Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671754Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671752Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.671765Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671767Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.671777Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671782Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-29T14:20:40.671788Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671800Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671797Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56 [INFO] [stdout] 2026-04-29T14:20:40.671812Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671816Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56 [INFO] [stdout] 2026-04-29T14:20:40.671822Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671835Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671834Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56 [INFO] [stdout] 2026-04-29T14:20:40.671847Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671854Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671857Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671866Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.671869Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671879Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671881Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671890Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.671891Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671904Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671905Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.671914Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.671917Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671927Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.671929Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.671953Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.671956Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.664994Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.677073Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.677110Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.677126Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.677136Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.677147Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.677160Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.677168Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.677179Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.677190Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.677199Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.677209Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.677220Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.677229Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.677240Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.677250Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.677259Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.677269Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.677279Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.677288Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.677298Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.677308Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.677317Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.677327Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.677337Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.677346Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.677356Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.677367Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.677376Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.677386Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.677398Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.677407Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.677417Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.677427Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.677436Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.677446Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.677457Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.677466Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.677476Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.677487Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.677495Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.677506Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.677517Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.677525Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.677536Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.677547Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.677555Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.677565Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.677576Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.677585Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.677595Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.677605Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.677614Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.677624Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.677635Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.677644Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.677654Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.677665Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.677675Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.677685Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.677696Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.677705Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.677721Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.677732Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.677741Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.677751Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.677762Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.677771Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.677781Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.677792Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.677801Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.677811Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.677822Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.677831Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.677841Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.677852Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.677861Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.677871Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.677881Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.677890Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.677900Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.677911Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.677920Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.677930Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.677956Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.677966Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-29T14:20:40.677979Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.677992Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17 [INFO] [stdout] 2026-04-29T14:20:40.678003Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.678016Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.678029Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.678042Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.678056Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2026-04-29T14:20:40.678073Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2026-04-29T14:20:40.678089Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2026-04-29T14:20:40.678106Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2026-04-29T14:20:40.678134Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27 [INFO] [stdout] 2026-04-29T14:20:40.678151Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27 [INFO] [stdout] 2026-04-29T14:20:40.678168Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26 [INFO] [stdout] 2026-04-29T14:20:40.678184Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38 [INFO] [stdout] 2026-04-29T14:20:40.678201Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23 [INFO] [stdout] 2026-04-29T14:20:40.678217Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23 [INFO] [stdout] 2026-04-29T14:20:40.678234Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26 [INFO] [stdout] 2026-04-29T14:20:40.678253Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 } clk=17 req.finish_time=37 [INFO] [stdout] 2026-04-29T14:20:40.678276Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678287Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678298Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678310Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678319Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678331Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678343Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678353Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678364Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678376Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678386Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678397Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678410Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678420Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678431Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678443Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678452Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678464Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678477Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678487Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678499Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678511Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678521Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678532Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678545Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678555Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678567Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678581Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678590Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678602Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678613Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678623Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678635Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678647Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678657Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678668Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678680Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678689Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678700Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678719Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678729Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678741Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678753Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678762Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678774Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678786Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678796Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678808Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678820Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678830Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678841Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678854Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678864Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678876Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678888Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.678901Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.678913Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.678926Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.671974Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.678980Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.679018Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.679040Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.678936Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.679078Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.679114Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.679136Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.679195Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.679217Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.679240Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.679261Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.679207Z DEBUG ramu_rs::test: recv req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 } [INFO] [stdout] 2026-04-29T14:20:40.679294Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.679348Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.679331Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.679384Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.679415Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.679445Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.679497Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.679477Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.679530Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.679562Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.679591Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.679644Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.679624Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.679681Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.679734Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.679716Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.679768Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.679802Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.679832Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.679863Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.679894Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.679924Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.679963Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.679996Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56 [INFO] [stdout] 2026-04-29T14:20:40.680010Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.679980Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40 [INFO] [stdout] 2026-04-29T14:20:40.680025Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.680084Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.680064Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.680120Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-29T14:20:40.680193Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.680164Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.680208Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2026-04-29T14:20:40.680269Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95 [INFO] [stdout] 2026-04-29T14:20:40.680303Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111 [INFO] [stdout] 2026-04-29T14:20:40.680332Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57 [INFO] [stdout] 2026-04-29T14:20:40.680249Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.680372Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2026-04-29T14:20:40.680437Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72 [INFO] [stdout] 2026-04-29T14:20:40.680465Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72 [INFO] [stdout] 2026-04-29T14:20:40.680417Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-29T14:20:40.680503Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72 [INFO] [stdout] 2026-04-29T14:20:40.680568Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72 [INFO] [stdout] 2026-04-29T14:20:40.680598Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111 [INFO] [stdout] 2026-04-29T14:20:40.680548Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56 [INFO] [stdout] 2026-04-29T14:20:40.680616Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95 [INFO] [stdout] 2026-04-29T14:20:40.680688Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.680703Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.680730Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.680745Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.680756Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.680777Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.680790Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.680666Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56 [INFO] [stdout] 2026-04-29T14:20:40.680802Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.680870Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.680900Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.680913Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.680848Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56 [INFO] [stdout] 2026-04-29T14:20:40.680985Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.680996Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.681030Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.681103Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.681067Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.681176Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.681210Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.681244Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.681275Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.681308Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.681337Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.681368Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.681396Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.681428Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.681474Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.681455Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.681550Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.681590Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.681532Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.681652Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.681688Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.681762Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.681806Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.681743Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.681864Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.681914Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.681895Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.681991Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.682025Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.682087Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.682067Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.682167Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.682145Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.682260Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.682299Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.682238Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.682362Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.682397Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.682459Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.682502Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.682441Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.682563Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.682621Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.682689Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.682668Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.682778Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.682818Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.682757Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.682884Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.682918Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.682980Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.683036Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.683070Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.683019Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.683126Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.683160Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56 [INFO] [stdout] 2026-04-29T14:20:40.683217Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.683200Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.683301Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.683338Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.683278Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.683396Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.683430Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.683492Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.683470Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-29T14:20:40.683569Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.683605Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2026-04-29T14:20:40.683551Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.683669Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.683738Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.683771Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.683701Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95 [INFO] [stdout] 2026-04-29T14:20:40.683834Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111 [INFO] [stdout] 2026-04-29T14:20:40.683871Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.683935Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.683911Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57 [INFO] [stdout] 2026-04-29T14:20:40.684016Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2026-04-29T14:20:40.684057Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.684137Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.684173Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.684112Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72 [INFO] [stdout] 2026-04-29T14:20:40.684233Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72 [INFO] [stdout] 2026-04-29T14:20:40.684274Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.684345Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.684381Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.684320Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72 [INFO] [stdout] 2026-04-29T14:20:40.684443Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72 [INFO] [stdout] 2026-04-29T14:20:40.684484Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.684555Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.684592Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.684529Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111 [INFO] [stdout] 2026-04-29T14:20:40.684654Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95 [INFO] [stdout] 2026-04-29T14:20:40.684695Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.684750Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.684790Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.684862Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.684842Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.684961Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.685001Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.684924Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.685067Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.685102Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.685167Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.685146Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.685248Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.685292Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.685228Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.685356Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.685388Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.685446Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.685428Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.685527Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.685569Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.685509Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.685632Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.685670Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.685737Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-29T14:20:40.685771Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.685718Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.685838Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.685873Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.663469Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.687525Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.685918Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.687576Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.687604Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.687728Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.687603Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.687643Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stderr] error: test failed, to rerun pass `--lib` [INFO] [stdout] 2026-04-29T14:20:40.687743Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.687893Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.687908Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.687918Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.681139Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.687985Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.688003Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.687974Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.688017Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.688032Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.688051Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.688062Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.688075Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.688026Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.688093Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.688106Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.687813Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=51 [INFO] [stdout] 2026-04-29T14:20:40.688119Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.688130Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.688128Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.688143Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.688145Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.688157Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.688159Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.688168Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.688174Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-29T14:20:40.688181Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.688189Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=67 [INFO] [stdout] 2026-04-29T14:20:40.688194Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.688207Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.688205Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=67 [INFO] [stdout] 2026-04-29T14:20:40.688219Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.688223Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=67 [INFO] [stdout] 2026-04-29T14:20:40.688233Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.688243Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688244Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.688254Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.688259Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.688267Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688273Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.688278Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.688284Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.688291Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688296Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.688301Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.688309Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.688314Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688320Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.688325Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.688333Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.688339Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688346Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.688349Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.688356Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.688361Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688369Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.688372Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.688382Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-29T14:20:40.688384Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688395Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.688393Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.688407Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688408Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-29T14:20:40.688417Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.688422Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=72 [INFO] [stdout] 2026-04-29T14:20:40.688432Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688435Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.688441Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.688454Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688450Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.688464Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.688466Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.688476Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688481Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-29T14:20:40.688486Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.688498Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688496Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=21 future=76 [INFO] [stdout] 2026-04-29T14:20:40.688509Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.688521Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688514Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=21 future=76 [INFO] [stdout] 2026-04-29T14:20:40.688532Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.688534Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=21 future=76 [INFO] [stdout] 2026-04-29T14:20:40.688544Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688556Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.688552Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=21 future=76 [INFO] [stdout] 2026-04-29T14:20:40.688568Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688570Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=27 future=82 [INFO] [stdout] 2026-04-29T14:20:40.688578Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.688592Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688590Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=27 future=82 [INFO] [stdout] 2026-04-29T14:20:40.688603Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-29T14:20:40.688608Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=95 future=81 [INFO] [stdout] 2026-04-29T14:20:40.688617Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=67 [INFO] [stdout] 2026-04-29T14:20:40.688625Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=57 future=93 [INFO] [stdout] 2026-04-29T14:20:40.688629Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.688645Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.688644Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=23 future=78 [INFO] [stdout] 2026-04-29T14:20:40.688660Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.688663Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=23 future=78 [INFO] [stdout] 2026-04-29T14:20:40.688675Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-29T14:20:40.688681Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=95 future=81 [INFO] [stdout] 2026-04-29T14:20:40.688689Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.688701Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 92 } clk=72 req.finish_time=92 [INFO] [stdout] 2026-04-29T14:20:40.688702Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=67 [INFO] [stdout] 2026-04-29T14:20:40.688725Z DEBUG ramu_rs::test: recv req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 92 } [INFO] [stdout] 2026-04-29T14:20:40.688727Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=51 future=106 [INFO] [stdout] 2026-04-29T14:20:40.688745Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=67 future=122 [INFO] [stdout] 2026-04-29T14:20:40.688762Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=51 future=68 [INFO] [stdout] 2026-04-29T14:20:40.688779Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=67 [INFO] [stdout] 2026-04-29T14:20:40.688797Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=83 [INFO] [stdout] 2026-04-29T14:20:40.688814Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=83 [INFO] [stdout] 2026-04-29T14:20:40.688830Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=83 [INFO] [stdout] 2026-04-29T14:20:40.688845Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=83 [INFO] [stdout] 2026-04-29T14:20:40.688861Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=67 future=122 [INFO] [stdout] 2026-04-29T14:20:40.688877Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=51 future=106 [INFO] [stdout] 2026-04-29T14:20:40.688905Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688916Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.688927Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.688956Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.688968Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.688980Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.688993Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.689003Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.689015Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.689027Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.689037Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.689048Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.689062Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.689072Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.689083Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.689097Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.689111Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.689123Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.689134Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.689144Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.689156Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.689167Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.689177Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.689189Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.689201Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.689211Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.689223Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.689236Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.689246Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.689257Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.689269Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.689278Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.689290Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.689303Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.689313Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.689324Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.689336Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.689346Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.689358Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.689370Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.689382Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.689393Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.689406Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.689416Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.689428Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.689439Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.689449Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.689461Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.689475Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=83 [INFO] [stdout] 2026-04-29T14:20:40.689486Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.689499Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.689513Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.689527Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-29T14:20:40.689541Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=21 future=87 [INFO] [stdout] 2026-04-29T14:20:40.689557Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=21 future=87 [INFO] [stdout] 2026-04-29T14:20:40.689573Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=21 future=87 [INFO] [stdout] 2026-04-29T14:20:40.689590Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=21 future=87 [INFO] [stdout] 2026-04-29T14:20:40.689606Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=36 future=102 [INFO] [stdout] 2026-04-29T14:20:40.689621Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=36 future=102 [INFO] [stdout] 2026-04-29T14:20:40.689638Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=106 future=117 [INFO] [stdout] 2026-04-29T14:20:40.689654Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=68 future=117 [INFO] [stdout] 2026-04-29T14:20:40.689672Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=23 future=89 [INFO] [stdout] 2026-04-29T14:20:40.689688Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=23 future=89 [INFO] [stdout] 2026-04-29T14:20:40.689704Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=42 future=108 [INFO] [stdout] 2026-04-29T14:20:40.689729Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=42 future=108 [INFO] [stdout] 2026-04-29T14:20:40.689747Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=106 future=117 [INFO] [stdout] 2026-04-29T14:20:40.689766Z DEBUG ramu_rs::controller: write request finished req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 83 } [INFO] [stdout] 2026-04-29T14:20:40.689783Z DEBUG ramu_rs::test: recv req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 83 } [INFO] [stdout] 2026-04-29T14:20:40.687935Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.690980Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.690999Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.691012Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.691026Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.691036Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.691048Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.691061Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.691072Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.691084Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.691097Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.691107Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.691120Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.691132Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.691143Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.691156Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.691168Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.691178Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.691196Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.691209Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.691219Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.691232Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.691245Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.691255Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.691267Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.691280Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-29T14:20:40.691290Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-29T14:20:40.691306Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-29T14:20:40.691320Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=72 [INFO] [stdout] 2026-04-29T14:20:40.691330Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.691350Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.691364Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-29T14:20:40.691378Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-29T14:20:40.691393Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=76 [INFO] [stdout] 2026-04-29T14:20:40.691410Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=76 [INFO] [stdout] 2026-04-29T14:20:40.691426Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=27 future=76 [INFO] [stdout] 2026-04-29T14:20:40.691443Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=27 future=76 [INFO] [stdout] 2026-04-29T14:20:40.691465Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=21 future=91 [INFO] [stdout] 2026-04-29T14:20:40.691482Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=21 future=91 [INFO] [stdout] 2026-04-29T14:20:40.691498Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=95 future=106 [INFO] [stdout] 2026-04-29T14:20:40.691514Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=57 future=106 [INFO] [stdout] 2026-04-29T14:20:40.691530Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=78 [INFO] [stdout] 2026-04-29T14:20:40.691546Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=78 [INFO] [stdout] 2026-04-29T14:20:40.691562Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=23 future=97 [INFO] [stdout] 2026-04-29T14:20:40.691576Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=23 future=97 [INFO] [stdout] 2026-04-29T14:20:40.691593Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=95 future=106 [INFO] [stdout] 2026-04-29T14:20:40.691617Z DEBUG ramu_rs::controller: write request finished req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 72 } [INFO] [stdout] 2026-04-29T14:20:40.691632Z DEBUG ramu_rs::test: recv req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 72 } [INFO] [stdout] 2026-04-29T14:20:40.688097Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.691784Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.691813Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.691836Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.691857Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.691872Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.691885Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.691898Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.691914Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.691957Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.691976Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.691994Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692006Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692018Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692030Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692044Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692063Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.692086Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.692101Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692115Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.692129Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.692144Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.692160Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2026-04-29T14:20:40.692181Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692193Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692207Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692220Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692234Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692248Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692261Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692285Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692299Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692312Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692326Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692338Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692352Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692365Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692377Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692391Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692408Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692423Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692436Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692457Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692470Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692484Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692497Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692510Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692523Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692536Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692550Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692563Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692577Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-29T14:20:40.692598Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2026-04-29T14:20:40.692689Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=1 [INFO] [stdout] 2026-04-29T14:20:40.692735Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 0] [INFO] [stdout] 2026-04-29T14:20:40.692767Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 0 [INFO] [stdout] 2026-04-29T14:20:40.692786Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=65 [INFO] [stdout] 2026-04-29T14:20:40.692804Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 1] [INFO] [stdout] 2026-04-29T14:20:40.692822Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 64 [INFO] [stdout] 2026-04-29T14:20:40.692839Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=257 [INFO] [stdout] 2026-04-29T14:20:40.692865Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 4] [INFO] [stdout] 2026-04-29T14:20:40.692886Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 256 [INFO] [stdout] test test::test_memory_diffrent_row ... ok [INFO] [stdout] test test::test_memory_write ... ok [INFO] [stdout] test test::test_memory_read_and_write ... ok [INFO] [stdout] test ddr4::tests::test_address ... ok [INFO] [stdout] test controller::tests::test_controller_simple_read ... FAILED [INFO] [stdout] [INFO] [stdout] failures: [INFO] [stdout] [INFO] [stdout] ---- controller::tests::test_controller_simple_read stdout ---- [INFO] [stdout] [INFO] [stdout] thread 'controller::tests::test_controller_simple_read' (17) panicked at src/controller.rs:300:9: [INFO] [stdout] assertion failed: controller.finished_queue.is_empty() [INFO] [stdout] stack backtrace: [INFO] [stdout] 0: 0x557b57f42e3a - std[e28293b1aa0f68bd]::backtrace_rs::backtrace::libunwind::trace [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/../../backtrace/src/backtrace/libunwind.rs:117:9 [INFO] [stdout] 1: 0x557b57f42e3a - std[e28293b1aa0f68bd]::backtrace_rs::backtrace::trace_unsynchronized:: [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/../../backtrace/src/backtrace/mod.rs:66:14 [INFO] [stdout] 2: 0x557b57f42e3a - std[e28293b1aa0f68bd]::sys::backtrace::_print_fmt [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/sys/backtrace.rs:74:9 [INFO] [stdout] 3: 0x557b57f42e3a - <::print::DisplayBacktrace as core[c1f1a4ba060b9bfa]::fmt::Display>::fmt [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/sys/backtrace.rs:44:26 [INFO] [stdout] 4: 0x557b57f5813a - ::fmt [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/core/src/fmt/rt.rs:152:76 [INFO] [stdout] 5: 0x557b57f5813a - core[c1f1a4ba060b9bfa]::fmt::write [INFO] [stdout] 6: 0x557b57f47772 - std[e28293b1aa0f68bd]::io::default_write_fmt::> [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/io/mod.rs:639:11 [INFO] [stdout] 7: 0x557b57f47772 - as std[e28293b1aa0f68bd]::io::Write>::write_fmt [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/io/mod.rs:1994:13 [INFO] [stdout] 8: 0x557b57f21e8f - ::print [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/sys/backtrace.rs:47:9 [INFO] [stdout] 9: 0x557b57f21e8f - std[e28293b1aa0f68bd]::panicking::default_hook::{closure#0} [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:292:27 [INFO] [stdout] 10: 0x557b57f3b229 - std[e28293b1aa0f68bd]::panicking::default_hook [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:316:9 [INFO] [stdout] 11: 0x557b57d3b14c - core[c1f1a4ba060b9bfa]::ops::function::Fn<(&'a std[e28293b1aa0f68bd]::panic::PanicHookInfo<'b>,), Output = ()> + core[c1f1a4ba060b9bfa]::marker::Sync + core[c1f1a4ba060b9bfa]::marker::Send> as core[c1f1a4ba060b9bfa]::ops::function::Fn<(&std[e28293b1aa0f68bd]::panic::PanicHookInfo,)>>::call [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/alloc/src/boxed.rs:2254:9 [INFO] [stdout] 12: 0x557b57d3b14c - test[273d7611820c9051]::test_main_with_exit_callback::::{closure#0} [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/test/src/lib.rs:145:21 [INFO] [stdout] 13: 0x557b57f3b3e2 - core[c1f1a4ba060b9bfa]::ops::function::Fn<(&'a std[e28293b1aa0f68bd]::panic::PanicHookInfo<'b>,), Output = ()> + core[c1f1a4ba060b9bfa]::marker::Sync + core[c1f1a4ba060b9bfa]::marker::Send> as core[c1f1a4ba060b9bfa]::ops::function::Fn<(&std[e28293b1aa0f68bd]::panic::PanicHookInfo,)>>::call [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/alloc/src/boxed.rs:2254:9 [INFO] [stdout] 14: 0x557b57f3b3e2 - std[e28293b1aa0f68bd]::panicking::panic_with_hook [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:833:13 [INFO] [stdout] 15: 0x557b57f21f7a - std[e28293b1aa0f68bd]::panicking::panic_handler::{closure#0} [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:691:13 [INFO] [stdout] 16: 0x557b57f198b9 - std[e28293b1aa0f68bd]::sys::backtrace::__rust_end_short_backtrace:: [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/sys/backtrace.rs:182:18 [INFO] [stdout] 17: 0x557b57f22c5d - __rustc[b7974e8690430dd9]::rust_begin_unwind [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:689:5 [INFO] [stdout] 18: 0x557b57f58a9c - core[c1f1a4ba060b9bfa]::panicking::panic_fmt [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/core/src/panicking.rs:80:14 [INFO] [stdout] 19: 0x557b57f58a62 - core[c1f1a4ba060b9bfa]::panicking::panic [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/core/src/panicking.rs:150:5 [INFO] [stdout] 20: 0x557b57d2390f - ramu_rs::controller::tests::test_controller_simple_read::h88bad8ee534c0479 [INFO] [stdout] at /opt/rustwide/workdir/src/controller.rs:300:9 [INFO] [stdout] 21: 0x557b57d23a07 - ramu_rs::controller::tests::test_controller_simple_read::{{closure}}::h65d5f937f0207ffb [INFO] [stdout] at /opt/rustwide/workdir/src/controller.rs:277:37 [INFO] [stdout] 22: 0x557b57d218f6 - core::ops::function::FnOnce::call_once::h8c7260dbf24cfdf9 [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/core/src/ops/function.rs:250:5 [INFO] [stdout] 23: 0x557b57d2f22b - core[c1f1a4ba060b9bfa]::result::Result<(), alloc[fdfd2bd8633a6659]::string::String> as core[c1f1a4ba060b9bfa]::ops::function::FnOnce<()>>::call_once [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/core/src/ops/function.rs:250:5 [INFO] [stdout] 24: 0x557b57d2f22b - test[273d7611820c9051]::__rust_begin_short_backtrace::, fn() -> core[c1f1a4ba060b9bfa]::result::Result<(), alloc[fdfd2bd8633a6659]::string::String>> [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/test/src/lib.rs:663:18 [INFO] [stdout] 25: 0x557b57d3bc1b - test[273d7611820c9051]::run_test_in_process::{closure#0} [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/test/src/lib.rs:686:74 [INFO] [stdout] 26: 0x557b57d3bc1b - as core[c1f1a4ba060b9bfa]::ops::function::FnOnce<()>>::call_once [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/core/src/panic/unwind_safe.rs:274:9 [INFO] [stdout] 27: 0x557b57d3bc1b - std[e28293b1aa0f68bd]::panicking::catch_unwind::do_call::, core[c1f1a4ba060b9bfa]::result::Result<(), alloc[fdfd2bd8633a6659]::string::String>> [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:581:40 [INFO] [stdout] 28: 0x557b57d3bc1b - std[e28293b1aa0f68bd]::panicking::catch_unwind::, core[c1f1a4ba060b9bfa]::panic::unwind_safe::AssertUnwindSafe> [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:544:19 [INFO] [stdout] 29: 0x557b57d3bc1b - std[e28293b1aa0f68bd]::panic::catch_unwind::, core[c1f1a4ba060b9bfa]::result::Result<(), alloc[fdfd2bd8633a6659]::string::String>> [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panic.rs:359:14 [INFO] [stdout] 30: 0x557b57d3bc1b - test[273d7611820c9051]::run_test_in_process [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/test/src/lib.rs:686:27 [INFO] [stdout] 31: 0x557b57d3bc1b - test[273d7611820c9051]::run_test::{closure#0} [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/test/src/lib.rs:607:43 [INFO] [stdout] 32: 0x557b57d37334 - test[273d7611820c9051]::run_test::{closure#1} [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/test/src/lib.rs:637:41 [INFO] [stdout] 33: 0x557b57d37334 - std[e28293b1aa0f68bd]::sys::backtrace::__rust_begin_short_backtrace:: [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/sys/backtrace.rs:166:18 [INFO] [stdout] 34: 0x557b57d3e822 - std[e28293b1aa0f68bd]::thread::lifecycle::spawn_unchecked::::{closure#1}::{closure#0} [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/thread/lifecycle.rs:91:13 [INFO] [stdout] 35: 0x557b57d3e822 - ::{closure#1}::{closure#0}> as core[c1f1a4ba060b9bfa]::ops::function::FnOnce<()>>::call_once [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/core/src/panic/unwind_safe.rs:274:9 [INFO] [stdout] 36: 0x557b57d3e822 - std[e28293b1aa0f68bd]::panicking::catch_unwind::do_call::::{closure#1}::{closure#0}>, ()> [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:581:40 [INFO] [stdout] 37: 0x557b57d3e822 - std[e28293b1aa0f68bd]::panicking::catch_unwind::<(), core[c1f1a4ba060b9bfa]::panic::unwind_safe::AssertUnwindSafe::{closure#1}::{closure#0}>> [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:544:19 [INFO] [stdout] 38: 0x557b57d3e822 - std[e28293b1aa0f68bd]::panic::catch_unwind::::{closure#1}::{closure#0}>, ()> [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panic.rs:359:14 [INFO] [stdout] 39: 0x557b57d3e822 - std[e28293b1aa0f68bd]::thread::lifecycle::spawn_unchecked::::{closure#1} [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/thread/lifecycle.rs:89:26 [INFO] [stdout] 40: 0x557b57d3e822 - ::{closure#1} as core[c1f1a4ba060b9bfa]::ops::function::FnOnce<()>>::call_once::{shim:vtable#0} [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/core/src/ops/function.rs:250:5 [INFO] [stdout] 41: 0x557b57f4271f - + core[c1f1a4ba060b9bfa]::marker::Send> as core[c1f1a4ba060b9bfa]::ops::function::FnOnce<()>>::call_once [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/alloc/src/boxed.rs:2240:9 [INFO] [stdout] 42: 0x557b57f4271f - ::new::thread_start [INFO] [stdout] at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/sys/thread/unix.rs:118:17 [INFO] [stdout] 43: 0x7653981acaa4 - [INFO] [stdout] 44: 0x765398239a64 - clone [INFO] [stdout] 45: 0x0 - [INFO] [stdout] [INFO] [stdout] [INFO] [stdout] failures: [INFO] [stdout] controller::tests::test_controller_simple_read [INFO] [stdout] [INFO] [stdout] test result: FAILED. 6 passed; 1 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.04s [INFO] [stdout] [INFO] running `Command { std: "docker" "inspect" "1d65627f326fe7067646176246534396beb8a0d6d40e5f346d289dbb6ec3d74a", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "1d65627f326fe7067646176246534396beb8a0d6d40e5f346d289dbb6ec3d74a", kill_on_drop: false }` [INFO] [stdout] 1d65627f326fe7067646176246534396beb8a0d6d40e5f346d289dbb6ec3d74a