[INFO] fetching crate ramu_rs 0.1.1... [INFO] testing ramu_rs-0.1.1 against master#562dee4820c458d823175268e41601d4c060588a for pr-154210-2 [INFO] extracting crate ramu_rs 0.1.1 into /workspace/builds/worker-5-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-5-tc1/source/Cargo.toml [INFO] validating manifest of crates.io crate ramu_rs 0.1.1 on toolchain 562dee4820c458d823175268e41601d4c060588a [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+562dee4820c458d823175268e41601d4c060588a" "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" "+562dee4820c458d823175268e41601d4c060588a" "generate-lockfile" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] [stderr] Updating crates.io index [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" "+562dee4820c458d823175268e41601d4c060588a" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] [stderr] Downloading crates ... [INFO] [stderr] Downloaded link-cplusplus v1.0.12 [INFO] [stderr] Downloaded scratch v1.0.9 [INFO] [stderr] Downloaded cxxbridge-flags v1.0.194 [INFO] [stderr] Downloaded cxxbridge-cmd v1.0.194 [INFO] [stderr] Downloaded enum-as-inner v0.5.1 [INFO] [stderr] Downloaded codespan-reporting v0.13.1 [INFO] [stderr] Downloaded cxx-build v1.0.194 [INFO] [stderr] Downloaded cxxbridge-macro v1.0.194 [INFO] [stderr] Downloaded cxx v1.0.194 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-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" "+562dee4820c458d823175268e41601d4c060588a" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }` [INFO] [stdout] 66c43b0b4f5f92da91a8f483b31583f78e339efb978777f80eef3fb72de356e3 [INFO] running `Command { std: "docker" "start" "-a" "66c43b0b4f5f92da91a8f483b31583f78e339efb978777f80eef3fb72de356e3", kill_on_drop: false }` [INFO] running `Command { std: "docker" "inspect" "66c43b0b4f5f92da91a8f483b31583f78e339efb978777f80eef3fb72de356e3", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "66c43b0b4f5f92da91a8f483b31583f78e339efb978777f80eef3fb72de356e3", kill_on_drop: false }` [INFO] [stdout] 66c43b0b4f5f92da91a8f483b31583f78e339efb978777f80eef3fb72de356e3 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-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=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-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" "+562dee4820c458d823175268e41601d4c060588a" "build" "--frozen" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 20b4e0f4ead21f9fc6ddb133aa16b227a4318397dea70256b14061b9ab9764a1 [INFO] running `Command { std: "docker" "start" "-a" "20b4e0f4ead21f9fc6ddb133aa16b227a4318397dea70256b14061b9ab9764a1", kill_on_drop: false }` [INFO] [stderr] Compiling syn v2.0.117 [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 winnow v0.5.40 [INFO] [stderr] Compiling link-cplusplus v1.0.12 [INFO] [stderr] Compiling tracing-core v0.1.36 [INFO] [stderr] Compiling regex-syntax v0.8.10 [INFO] [stderr] Compiling cxxbridge-flags v1.0.194 [INFO] [stderr] Compiling cxx v1.0.194 [INFO] [stderr] Compiling foldhash v0.2.0 [INFO] [stderr] Compiling tracing-log v0.2.0 [INFO] [stderr] Compiling indexmap v2.14.0 [INFO] [stderr] Compiling regex-automata v0.4.14 [INFO] [stderr] Compiling toml_edit v0.19.15 [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 serde_derive v1.0.228 [INFO] [stderr] Compiling tracing-attributes v0.1.31 [INFO] [stderr] Compiling cxxbridge-macro v1.0.194 [INFO] [stderr] Compiling num_enum v0.5.11 [INFO] [stderr] Compiling tracing v0.1.44 [INFO] [stderr] Compiling tracing-subscriber v0.3.23 [INFO] [stderr] Compiling serde v1.0.228 [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 43.20s [INFO] running `Command { std: "docker" "inspect" "20b4e0f4ead21f9fc6ddb133aa16b227a4318397dea70256b14061b9ab9764a1", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "20b4e0f4ead21f9fc6ddb133aa16b227a4318397dea70256b14061b9ab9764a1", kill_on_drop: false }` [INFO] [stdout] 20b4e0f4ead21f9fc6ddb133aa16b227a4318397dea70256b14061b9ab9764a1 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-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=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-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" "+562dee4820c458d823175268e41601d4c060588a" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 5215a0c1ce539c4bab9c0728cbb26a8778a0f1ec9e6442534510db9cbb17496e [INFO] running `Command { std: "docker" "start" "-a" "5215a0c1ce539c4bab9c0728cbb26a8778a0f1ec9e6442534510db9cbb17496e", 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 1.93s [INFO] running `Command { std: "docker" "inspect" "5215a0c1ce539c4bab9c0728cbb26a8778a0f1ec9e6442534510db9cbb17496e", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "5215a0c1ce539c4bab9c0728cbb26a8778a0f1ec9e6442534510db9cbb17496e", kill_on_drop: false }` [INFO] [stdout] 5215a0c1ce539c4bab9c0728cbb26a8778a0f1ec9e6442534510db9cbb17496e [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-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=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-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" "+562dee4820c458d823175268e41601d4c060588a" "test" "--frozen", kill_on_drop: false }` [INFO] [stdout] bd67600bb0d5dd2beb6adbd799b685a43d5163fc2a185f194c7154dd8dcbe41c [INFO] running `Command { std: "docker" "start" "-a" "bd67600bb0d5dd2beb6adbd799b685a43d5163fc2a185f194c7154dd8dcbe41c", kill_on_drop: false }` [INFO] [stderr] Finished `test` profile [unoptimized + debuginfo] target(s) in 0.15s [INFO] [stderr] Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/ramu_rs-eb1337f2a05f511a) [INFO] [stdout] [INFO] [stdout] running 8 tests [INFO] [stdout] test config::tests::dum_config ... ignored [INFO] [stdout] 2026-04-19T22:53:48.260762Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2026-04-19T22:53:48.260827Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2026-04-19T22:53:48.260895Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2026-04-19T22:53:48.260908Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2026-04-19T22:53:48.260598Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2026-04-19T22:53:48.261182Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2026-04-19T22:53:48.261097Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] test utils::tests::test_addr ... ok [INFO] [stdout] 2026-04-19T22:53:48.261283Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2026-04-19T22:53:48.261293Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2026-04-19T22:53:48.261303Z  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-19T22:53:48.261313Z  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-19T22:53:48.261350Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261356Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261364Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261374Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261377Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261389Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261390Z  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-19T22:53:48.261407Z  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-19T22:53:48.261404Z  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-19T22:53:48.261422Z  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-19T22:53:48.261425Z  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-19T22:53:48.261437Z  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-19T22:53:48.261443Z  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-19T22:53:48.261454Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261460Z  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-19T22:53:48.261466Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261477Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261479Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261493Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261492Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261506Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261508Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261523Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261518Z  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-19T22:53:48.261538Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261539Z  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-19T22:53:48.261554Z  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-19T22:53:48.261553Z  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-19T22:53:48.261577Z  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-19T22:53:48.261570Z  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-19T22:53:48.261594Z  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-19T22:53:48.261602Z  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-19T22:53:48.261613Z  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-19T22:53:48.261625Z  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-19T22:53:48.261646Z  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-19T22:53:48.261656Z  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-19T22:53:48.261680Z  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-19T22:53:48.261673Z  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-19T22:53:48.261696Z  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-19T22:53:48.261705Z  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-19T22:53:48.261711Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2026-04-19T22:53:48.261711Z  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-19T22:53:48.261737Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2026-04-19T22:53:48.261733Z  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-19T22:53:48.261737Z  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-19T22:53:48.261752Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2026-04-19T22:53:48.261753Z  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-19T22:53:48.261757Z  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-19T22:53:48.261764Z  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-19T22:53:48.261775Z  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-19T22:53:48.261768Z  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-19T22:53:48.261789Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261796Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261802Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261799Z  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-19T22:53:48.261810Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261815Z  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-19T22:53:48.261823Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261817Z  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-19T22:53:48.261853Z  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-19T22:53:48.261860Z  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-19T22:53:48.261830Z  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-19T22:53:48.261871Z  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-19T22:53:48.261876Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261886Z  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-19T22:53:48.261889Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261903Z  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-19T22:53:48.261913Z  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-19T22:53:48.261918Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261931Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261928Z  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-19T22:53:48.261944Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261945Z  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-19T22:53:48.261956Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261959Z  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-19T22:53:48.261975Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261983Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261996Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.261990Z  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-19T22:53:48.262008Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262011Z  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-19T22:53:48.262022Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262028Z  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-19T22:53:48.262035Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262048Z  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-19T22:53:48.262046Z  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-19T22:53:48.262068Z  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-19T22:53:48.262082Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262078Z  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-19T22:53:48.262095Z  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-19T22:53:48.262109Z  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-19T22:53:48.262104Z  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-19T22:53:48.262125Z  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-19T22:53:48.262139Z  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-19T22:53:48.262134Z  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-19T22:53:48.262152Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262158Z  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-19T22:53:48.262165Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262175Z  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-19T22:53:48.262177Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262192Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262191Z  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-19T22:53:48.262205Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262223Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262221Z  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-19T22:53:48.262236Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262238Z  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-19T22:53:48.262250Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262258Z  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-19T22:53:48.262264Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262273Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262277Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262288Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262290Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262304Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262301Z  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-19T22:53:48.262317Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262319Z  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-19T22:53:48.262331Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262341Z  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-19T22:53:48.262345Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262360Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262358Z  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-19T22:53:48.262374Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262378Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262388Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262392Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262401Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262406Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262415Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262421Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262428Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262435Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262442Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262455Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262450Z  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-19T22:53:48.262469Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262476Z  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-19T22:53:48.262484Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262492Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262498Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262506Z  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-19T22:53:48.262512Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262521Z  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-19T22:53:48.262526Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262536Z  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-19T22:53:48.262540Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262551Z  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-19T22:53:48.262562Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2026-04-19T22:53:48.262565Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262578Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262591Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262603Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262617Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262629Z  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-19T22:53:48.262661Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2026-04-19T22:53:48.262692Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.262705Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.262720Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2026-04-19T22:53:48.262736Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.262751Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.262694Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262765Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.262776Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262779Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.262789Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262796Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.262802Z  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-19T22:53:48.262810Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2026-04-19T22:53:48.262820Z  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-19T22:53:48.262828Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2026-04-19T22:53:48.262852Z  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-19T22:53:48.262861Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2026-04-19T22:53:48.262871Z  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-19T22:53:48.262881Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2026-04-19T22:53:48.262890Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262892Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2026-04-19T22:53:48.262903Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262900Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2026-04-19T22:53:48.262911Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2026-04-19T22:53:48.262915Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262918Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2026-04-19T22:53:48.262925Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2026-04-19T22:53:48.262928Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262940Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262936Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2026-04-19T22:53:48.262937Z  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-19T22:53:48.262955Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2026-04-19T22:53:48.261885Z  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-19T22:53:48.262970Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262953Z  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-19T22:53:48.262983Z  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-19T22:53:48.262991Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263002Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263005Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.262998Z  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-19T22:53:48.263014Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263019Z  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-19T22:53:48.263020Z  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-19T22:53:48.263027Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263036Z  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-19T22:53:48.263041Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263054Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263053Z  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-19T22:53:48.263040Z  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-19T22:53:48.263070Z  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-19T22:53:48.263067Z  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-19T22:53:48.263073Z  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-19T22:53:48.263086Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263088Z  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-19T22:53:48.263100Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263102Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263113Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263114Z  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-19T22:53:48.263098Z  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-19T22:53:48.263238Z  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-19T22:53:48.263266Z  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] test scheduler::tests::test ... ok [INFO] [stdout] 2026-04-19T22:53:48.263283Z  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-19T22:53:48.263127Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263298Z  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-19T22:53:48.263313Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263325Z  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-19T22:53:48.263334Z  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-19T22:53:48.263340Z  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-19T22:53:48.263356Z  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-19T22:53:48.263361Z  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-19T22:53:48.263376Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263373Z  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-19T22:53:48.263388Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263401Z  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-19T22:53:48.263393Z  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-19T22:53:48.263416Z  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-19T22:53:48.263434Z  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-19T22:53:48.263425Z  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-19T22:53:48.263449Z  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-19T22:53:48.263466Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263452Z  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-19T22:53:48.263479Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263491Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263484Z  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-19T22:53:48.263503Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263509Z  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-19T22:53:48.263516Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263528Z  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-19T22:53:48.263530Z  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-19T22:53:48.263554Z  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-19T22:53:48.263543Z  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-19T22:53:48.263570Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263571Z  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-19T22:53:48.263584Z  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-19T22:53:48.263586Z  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-19T22:53:48.263599Z  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-19T22:53:48.263604Z  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-19T22:53:48.263614Z  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-19T22:53:48.263619Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263628Z  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-19T22:53:48.263633Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263643Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263646Z  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-19T22:53:48.263657Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263664Z  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-19T22:53:48.263671Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263682Z  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-19T22:53:48.263684Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263699Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263698Z  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-19T22:53:48.263713Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263716Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263727Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263729Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263741Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263742Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263755Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263756Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263769Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263769Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263783Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263784Z  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-19T22:53:48.263799Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263805Z  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-19T22:53:48.263812Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263819Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263827Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263844Z  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-19T22:53:48.263857Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263860Z  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-19T22:53:48.263872Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263874Z  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-19T22:53:48.263886Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263888Z  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-19T22:53:48.263900Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263902Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263914Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263915Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263928Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263929Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263942Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263944Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263956Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263957Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263977Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263971Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263993Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263992Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264006Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264008Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264019Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264022Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264032Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264037Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264044Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264051Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264057Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264067Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264070Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264081Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2026-04-19T22:53:48.264083Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264095Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264113Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264126Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264138Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264151Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264164Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264173Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2026-04-19T22:53:48.264176Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264191Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264194Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264204Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264206Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.264216Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264221Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2026-04-19T22:53:48.264229Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264234Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.264242Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264249Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.264254Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264264Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.264267Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264278Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.264280Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264291Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.264294Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2026-04-19T22:53:48.264301Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2026-04-19T22:53:48.264319Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2026-04-19T22:53:48.264337Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2026-04-19T22:53:48.264355Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2026-04-19T22:53:48.264366Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264376Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.264373Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2026-04-19T22:53:48.264389Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=0 [INFO] [stdout] 2026-04-19T22:53:48.264391Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2026-04-19T22:53:48.264400Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.264408Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2026-04-19T22:53:48.264414Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.264427Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.264426Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2026-04-19T22:53:48.264440Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.264442Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2026-04-19T22:53:48.264453Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.264458Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2026-04-19T22:53:48.264463Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=0 [INFO] [stdout] 2026-04-19T22:53:48.264477Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2026-04-19T22:53:48.264479Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=39 [INFO] [stdout] 2026-04-19T22:53:48.264497Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264496Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=55 [INFO] [stdout] 2026-04-19T22:53:48.264513Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.264512Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=1 [INFO] [stdout] 2026-04-19T22:53:48.264526Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.264529Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=0 [INFO] [stdout] 2026-04-19T22:53:48.264539Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264545Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=16 [INFO] [stdout] 2026-04-19T22:53:48.264550Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.264563Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.264561Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=16 [INFO] [stdout] 2026-04-19T22:53:48.264577Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264577Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=16 [INFO] [stdout] 2026-04-19T22:53:48.264587Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.264594Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=16 [INFO] [stdout] 2026-04-19T22:53:48.264599Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.264612Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264610Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=55 [INFO] [stdout] 2026-04-19T22:53:48.264622Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.264627Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=39 [INFO] [stdout] 2026-04-19T22:53:48.264634Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.264645Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264646Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264654Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.264656Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.264666Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.264668Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.264677Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264681Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264687Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.264690Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.264698Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.264702Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.264709Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264715Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264719Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.264726Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.264730Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.264739Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.264742Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264751Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264751Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.264762Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.264763Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.264776Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264774Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.264786Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.264789Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264798Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.264800Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.264809Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264813Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.264819Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.264825Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264853Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.264866Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.264880Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264889Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.264901Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.264914Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264925Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.264936Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.264950Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.262631Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264960Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.264980Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.264978Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.264994Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.264995Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265004Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.265008Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265046Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265059Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265071Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265083Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.263137Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2026-04-19T22:53:48.265159Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2026-04-19T22:53:48.265017Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.265223Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2026-04-19T22:53:48.265246Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.265243Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.265095Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265279Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.265294Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.265308Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.265279Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265318Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.265321Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265331Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.265336Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265345Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.265351Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265355Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.265367Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.265380Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.265390Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.265402Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.265414Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.265424Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.265436Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.265449Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.265459Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.265258Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.265495Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.265471Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.265524Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.265535Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.265549Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.265561Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.265364Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265575Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.265579Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265585Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.265594Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265597Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.265610Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.265607Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265620Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.265633Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.265645Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.265535Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.265655Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.265661Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.265668Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.265676Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.265680Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.265686Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.265691Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.265697Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.265703Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.265709Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.265762Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.265716Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.265622Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265785Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.265787Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265801Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.265829Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.265815Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.265853Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.265856Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.265863Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.265868Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.265874Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.265881Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.265886Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.265890Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.265934Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.265802Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265955Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.265961Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.265977Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.266052Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.266066Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.265949Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.266134Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266147Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.266159Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.266170Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266180Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.266190Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.266202Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266211Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.266222Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.266233Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266242Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.266252Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.266263Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266273Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.266284Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.266295Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266305Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.266316Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.266328Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266337Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.266347Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.266358Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266368Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.266379Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.266391Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266400Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.266411Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.266422Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266433Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.266444Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.266456Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266466Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.266477Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.266489Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266498Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.266509Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.266522Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266531Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.266543Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.266554Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266564Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.266575Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.266588Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266597Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.266609Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.266621Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266631Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.266642Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.266655Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266665Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.266677Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.266688Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266698Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.266708Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.266720Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266730Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.266743Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.266754Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266763Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.266774Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.266786Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266795Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.266806Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.266818Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266828Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.266856Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.266869Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266878Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.266889Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.266900Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266910Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.266922Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.266935Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.266945Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.266956Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.266969Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=17 [INFO] [stdout] 2026-04-19T22:53:48.266987Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.263129Z  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-19T22:53:48.267000Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.267013Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.267026Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.267040Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=21 [INFO] [stdout] 2026-04-19T22:53:48.267057Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=21 [INFO] [stdout] 2026-04-19T22:53:48.267074Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=0 future=21 [INFO] [stdout] 2026-04-19T22:53:48.267009Z  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-19T22:53:48.267234Z  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-19T22:53:48.267338Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.267389Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.267436Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.267487Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.267537Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.267586Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.267635Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.267684Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.267733Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.267784Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.267847Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.267905Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.267954Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.268011Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.268061Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.268111Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.268162Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.268218Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.268251Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.268372Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.268410Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.268440Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.266025Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.269861Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.269897Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.269895Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.269911Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.269917Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.269924Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.266079Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.269932Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2026-04-19T22:53:48.269937Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.269944Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.269950Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.269963Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:53:48.269962Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.269981Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2026-04-19T22:53:48.269984Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.269994Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.270005Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.270018Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17 [INFO] [stdout] 2026-04-19T22:53:48.270029Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2026-04-19T22:53:48.270031Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.270048Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270047Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.270060Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.270061Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.270062Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=1 [INFO] [stdout] 2026-04-19T22:53:48.270076Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.270090Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 0] [INFO] [stdout] 2026-04-19T22:53:48.270090Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2026-04-19T22:53:48.270108Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 0 [INFO] [stdout] 2026-04-19T22:53:48.270107Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2026-04-19T22:53:48.270121Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=65 [INFO] [stdout] 2026-04-19T22:53:48.270126Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2026-04-19T22:53:48.270074Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2026-04-19T22:53:48.270143Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 1] [INFO] [stdout] 2026-04-19T22:53:48.270143Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2026-04-19T22:53:48.270147Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.270160Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 64 [INFO] [stdout] 2026-04-19T22:53:48.270162Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.270161Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27 [INFO] [stdout] 2026-04-19T22:53:48.270174Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=257 [INFO] [stdout] 2026-04-19T22:53:48.270175Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.270178Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27 [INFO] [stdout] 2026-04-19T22:53:48.270189Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.270190Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 4] [INFO] [stdout] 2026-04-19T22:53:48.270195Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26 [INFO] [stdout] 2026-04-19T22:53:48.270203Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.270206Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 256 [INFO] [stdout] 2026-04-19T22:53:48.270213Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38 [INFO] [stdout] 2026-04-19T22:53:48.270215Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2026-04-19T22:53:48.270231Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23 [INFO] [stdout] 2026-04-19T22:53:48.270234Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2026-04-19T22:53:48.270249Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23 [INFO] [stdout] 2026-04-19T22:53:48.270253Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2026-04-19T22:53:48.270271Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2026-04-19T22:53:48.270270Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26 [INFO] [stdout] 2026-04-19T22:53:48.270295Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] test ddr4::tests::test_address ... ok [INFO] [stdout] 2026-04-19T22:53:48.270306Z 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-19T22:53:48.270314Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2026-04-19T22:53:48.264829Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.270329Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270330Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2026-04-19T22:53:48.270340Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270341Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270348Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2026-04-19T22:53:48.270353Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.270366Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2026-04-19T22:53:48.270354Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.270381Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270383Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2026-04-19T22:53:48.270388Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.270394Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270402Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270401Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2026-04-19T22:53:48.270407Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.270413Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.270421Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270422Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270425Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.270432Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270433Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.270436Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270444Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.270446Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.270447Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.270457Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270459Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.270468Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270471Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270482Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.270481Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.270493Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.270496Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270504Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270506Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270519Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.270522Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.270531Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.270537Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270543Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270548Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270552Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.270560Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.270563Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.270573Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270575Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270583Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270584Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.270595Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.270596Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.270609Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270609Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270618Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.270620Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270629Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.270633Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.270641Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270646Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270650Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.270656Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270661Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.270666Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.270673Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270679Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270682Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.270689Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270693Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.270701Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.270705Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=16 [INFO] [stdout] 2026-04-19T22:53:48.270714Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270716Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.270724Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270730Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.270736Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.270744Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.270748Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270758Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270757Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.270770Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.270772Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=20 [INFO] [stdout] 2026-04-19T22:53:48.270782Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270792Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270788Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=20 [INFO] [stdout] 2026-04-19T22:53:48.270804Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.270806Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=20 [INFO] [stdout] 2026-04-19T22:53:48.270818Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270822Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=20 [INFO] [stdout] 2026-04-19T22:53:48.270829Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270858Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.270853Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=26 [INFO] [stdout] 2026-04-19T22:53:48.270870Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270870Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=26 [INFO] [stdout] 2026-04-19T22:53:48.270879Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270889Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.270886Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=39 future=25 [INFO] [stdout] 2026-04-19T22:53:48.270900Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270902Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=1 future=37 [INFO] [stdout] 2026-04-19T22:53:48.270910Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270921Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.270919Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=22 [INFO] [stdout] 2026-04-19T22:53:48.270932Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270935Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=22 [INFO] [stdout] 2026-04-19T22:53:48.270942Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270952Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.270951Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=39 future=25 [INFO] [stdout] 2026-04-19T22:53:48.270964Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.270969Z 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-19T22:53:48.270980Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.270992Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.271006Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271015Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.271026Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.271038Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271048Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.271059Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.271077Z 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-19T22:53:48.271091Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271100Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.271111Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.271123Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271133Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.271145Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.271156Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271166Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.271177Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.271189Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40 [INFO] [stdout] 2026-04-19T22:53:48.271199Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.271213Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.271226Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.271239Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:53:48.271252Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56 [INFO] [stdout] 2026-04-19T22:53:48.271266Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56 [INFO] [stdout] 2026-04-19T22:53:48.271281Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56 [INFO] [stdout] 2026-04-19T22:53:48.271299Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271309Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.271321Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271331Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.271343Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271353Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.271364Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271374Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.271385Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271395Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.271408Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271418Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.271439Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271449Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.271460Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271469Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.271481Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271489Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.271500Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271511Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.271530Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271540Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.271552Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271562Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.271574Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271584Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.271596Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271605Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.271618Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271627Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.271639Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271648Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.271661Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56 [INFO] [stdout] 2026-04-19T22:53:48.271672Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.271684Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.271698Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.271711Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:53:48.271724Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.271735Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2026-04-19T22:53:48.271751Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95 [INFO] [stdout] 2026-04-19T22:53:48.271768Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111 [INFO] [stdout] 2026-04-19T22:53:48.271784Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57 [INFO] [stdout] 2026-04-19T22:53:48.271801Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2026-04-19T22:53:48.271817Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72 [INFO] [stdout] 2026-04-19T22:53:48.271855Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72 [INFO] [stdout] 2026-04-19T22:53:48.271874Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72 [INFO] [stdout] 2026-04-19T22:53:48.271890Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72 [INFO] [stdout] 2026-04-19T22:53:48.271915Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111 [INFO] [stdout] 2026-04-19T22:53:48.271937Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95 [INFO] [stdout] 2026-04-19T22:53:48.271963Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.271987Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.272005Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.272025Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.272042Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.272059Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.272078Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.272095Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.272113Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.272132Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.272150Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.272168Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.272187Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.272203Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.272221Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.272239Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.272256Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.272273Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.272293Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.272310Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.272329Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.272348Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.272366Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.272384Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.272402Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.272419Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.272436Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.272455Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.272471Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.272488Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.272506Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.272524Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.272543Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.272562Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.272579Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.272597Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.272616Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.272632Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.272651Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.272670Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.272687Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.272704Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.272723Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.272740Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.272758Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.272776Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.272792Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.272810Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.267091Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=0 future=21 [INFO] [stdout] 2026-04-19T22:53:48.272888Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=0 future=36 [INFO] [stdout] 2026-04-19T22:53:48.272907Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=0 future=36 [INFO] [stdout] 2026-04-19T22:53:48.272936Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=40 future=51 [INFO] [stdout] 2026-04-19T22:53:48.272954Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=2 future=51 [INFO] [stdout] 2026-04-19T22:53:48.272977Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=23 [INFO] [stdout] 2026-04-19T22:53:48.272995Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=23 [INFO] [stdout] 2026-04-19T22:53:48.273012Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=0 future=42 [INFO] [stdout] 2026-04-19T22:53:48.273029Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=0 future=42 [INFO] [stdout] 2026-04-19T22:53:48.273047Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=40 future=51 [INFO] [stdout] 2026-04-19T22:53:48.273072Z 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-19T22:53:48.273091Z 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-19T22:53:48.273105Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273116Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273127Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273139Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273149Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273161Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273174Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273185Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273197Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273212Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273221Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273233Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273246Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273256Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273267Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273279Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273290Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273302Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273314Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273324Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273336Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273349Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273359Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273371Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273384Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273395Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273406Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273418Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273429Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273440Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273454Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273464Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273475Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273488Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273498Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273510Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273523Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273535Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273546Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273559Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273569Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273581Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273594Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273604Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273616Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273629Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273640Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273652Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273664Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273675Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273687Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273700Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273710Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273722Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273735Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273745Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273757Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273769Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273779Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273791Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273804Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273815Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273826Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273857Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273866Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273878Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273889Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273899Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273909Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273921Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273931Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273942Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273953Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.273963Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.273979Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.273992Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274001Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.274013Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.274025Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274035Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.274046Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.274058Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274067Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.274078Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.274089Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274097Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.274108Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.274119Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274129Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.274139Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.274151Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274160Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.274171Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.274184Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274194Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.274204Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.274215Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274224Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.274234Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.274246Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274255Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.274266Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.274278Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=51 [INFO] [stdout] 2026-04-19T22:53:48.274290Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.274304Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.274318Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.274332Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:53:48.274347Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=67 [INFO] [stdout] 2026-04-19T22:53:48.274364Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=67 [INFO] [stdout] 2026-04-19T22:53:48.274380Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=67 [INFO] [stdout] 2026-04-19T22:53:48.274398Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274408Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.274420Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274430Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.274442Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274452Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.274464Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274474Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.274487Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274497Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.274508Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274518Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.274529Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274538Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.274549Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274559Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.274571Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274581Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.274593Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274602Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.274613Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274622Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.274632Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274642Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.274654Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274664Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.274674Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274683Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.274695Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274704Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.274716Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.274726Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.274738Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=67 [INFO] [stdout] 2026-04-19T22:53:48.274749Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.274763Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.274778Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.274790Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:53:48.274803Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.274814Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=67 [INFO] [stdout] 2026-04-19T22:53:48.274831Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=51 future=106 [INFO] [stdout] 2026-04-19T22:53:48.274865Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=67 future=122 [INFO] [stdout] 2026-04-19T22:53:48.274881Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=51 future=68 [INFO] [stdout] 2026-04-19T22:53:48.274899Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=67 [INFO] [stdout] 2026-04-19T22:53:48.274916Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=83 [INFO] [stdout] 2026-04-19T22:53:48.274932Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=83 [INFO] [stdout] 2026-04-19T22:53:48.274948Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=83 [INFO] [stdout] 2026-04-19T22:53:48.274964Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=83 [INFO] [stdout] 2026-04-19T22:53:48.274986Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=67 future=122 [INFO] [stdout] 2026-04-19T22:53:48.275001Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=51 future=106 [INFO] [stdout] 2026-04-19T22:53:48.275020Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.275030Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.275041Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.275053Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.275063Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.275075Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.275089Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.275098Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.275110Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.275121Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.275131Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.275142Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.275154Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.275164Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.275174Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.275187Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.275197Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.275208Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.275220Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.275230Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.275242Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.275254Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.275264Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.275276Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.275288Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.275298Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.275309Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.275319Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.275329Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.275340Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.275352Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.275361Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.275372Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.275383Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.275394Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.275405Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.275417Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.275427Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.275438Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.275450Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.275460Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.275471Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.275482Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.275491Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.275501Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.275512Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.275521Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.275532Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.275546Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=83 [INFO] [stdout] 2026-04-19T22:53:48.275557Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.275570Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.275583Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.275595Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:53:48.275609Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=21 future=87 [INFO] [stdout] 2026-04-19T22:53:48.275625Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=21 future=87 [INFO] [stdout] 2026-04-19T22:53:48.275640Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=21 future=87 [INFO] [stdout] 2026-04-19T22:53:48.275655Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=21 future=87 [INFO] [stdout] 2026-04-19T22:53:48.275672Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=36 future=102 [INFO] [stdout] 2026-04-19T22:53:48.275691Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=36 future=102 [INFO] [stdout] 2026-04-19T22:53:48.275709Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=106 future=117 [INFO] [stdout] 2026-04-19T22:53:48.275726Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=68 future=117 [INFO] [stdout] 2026-04-19T22:53:48.275743Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=23 future=89 [INFO] [stdout] 2026-04-19T22:53:48.275760Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=23 future=89 [INFO] [stdout] 2026-04-19T22:53:48.275776Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=42 future=108 [INFO] [stdout] 2026-04-19T22:53:48.275792Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=42 future=108 [INFO] [stdout] 2026-04-19T22:53:48.275809Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=106 future=117 [INFO] [stdout] 2026-04-19T22:53:48.272830Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=72 [INFO] [stdout] 2026-04-19T22:53:48.270460Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.280876Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.280893Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.280902Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.280913Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.280918Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.280929Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.280932Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:53:48.280939Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.280951Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.280948Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=21 future=76 [INFO] [stdout] 2026-04-19T22:53:48.280963Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.280965Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=21 future=76 [INFO] [stdout] 2026-04-19T22:53:48.280978Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.280989Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.280988Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=21 future=76 [INFO] [stdout] 2026-04-19T22:53:48.281001Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.281004Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=21 future=76 [INFO] [stdout] 2026-04-19T22:53:48.281010Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.281021Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.281021Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=27 future=82 [INFO] [stdout] 2026-04-19T22:53:48.281033Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.281042Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.281038Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=27 future=82 [INFO] [stdout] 2026-04-19T22:53:48.281053Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.281058Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=95 future=81 [INFO] [stdout] 2026-04-19T22:53:48.281065Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.281076Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.281074Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=57 future=93 [INFO] [stdout] 2026-04-19T22:53:48.281087Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.281091Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=23 future=78 [INFO] [stdout] 2026-04-19T22:53:48.281098Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.281109Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.281107Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=23 future=78 [INFO] [stdout] 2026-04-19T22:53:48.281120Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.281124Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=95 future=81 [INFO] [stdout] 2026-04-19T22:53:48.281132Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.281142Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.281143Z 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-19T22:53:48.281153Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.281164Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.281166Z 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-19T22:53:48.281174Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.281185Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.281196Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.281205Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.281219Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.281231Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.281240Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.281252Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.281263Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.281273Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.281284Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.281295Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.281304Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.281315Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.281334Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.281344Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.275827Z 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-19T22:53:48.281355Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.281366Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.281364Z 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-19T22:53:48.281376Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.281387Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.281399Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.281408Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.281419Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.281431Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.281440Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.281451Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.281463Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.281473Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.281485Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.281497Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.281511Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.281522Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.281533Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.281542Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.281553Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.281564Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.281573Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.281584Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.281595Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.281605Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.281616Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.281628Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.281637Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.281648Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.281660Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.281669Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.281680Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.281692Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.281701Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.281712Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.281724Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.281734Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.281745Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.281757Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.281766Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.281778Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.281790Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.281800Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.281811Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.281822Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.281832Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.281859Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.281871Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:53:48.281881Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:53:48.281892Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:53:48.281904Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17 [INFO] [stdout] 2026-04-19T22:53:48.281916Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.281928Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.281941Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.281954Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.281973Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2026-04-19T22:53:48.281990Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2026-04-19T22:53:48.282007Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2026-04-19T22:53:48.282023Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2026-04-19T22:53:48.282039Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27 [INFO] [stdout] 2026-04-19T22:53:48.282056Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27 [INFO] [stdout] 2026-04-19T22:53:48.282072Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26 [INFO] [stdout] 2026-04-19T22:53:48.282088Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38 [INFO] [stdout] 2026-04-19T22:53:48.282106Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23 [INFO] [stdout] 2026-04-19T22:53:48.282122Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23 [INFO] [stdout] 2026-04-19T22:53:48.282137Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26 [INFO] [stdout] 2026-04-19T22:53:48.282153Z 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-19T22:53:48.282172Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282181Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282192Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282203Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282212Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282223Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282241Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282251Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282262Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282274Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282284Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282296Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282308Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282318Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282330Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282342Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282351Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282362Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282374Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282384Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282397Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282409Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282418Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282429Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282440Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282449Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282459Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282469Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282477Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282487Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282498Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282507Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282518Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282530Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282539Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282550Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282567Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282577Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282589Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282601Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282611Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282623Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282635Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282644Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282655Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282666Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282675Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282686Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282700Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282709Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282721Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282733Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282742Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282753Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282765Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282775Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282787Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.282800Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.282809Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.282820Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.287868Z 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-19T22:53:48.287946Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.287991Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.288062Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.288149Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.288201Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.288243Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.288322Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.288411Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.288550Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:53:48.288687Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40 [INFO] [stdout] test test::test_memory_diffrent_row ... ok [INFO] [stdout] test test::test_memory_write ... ok [INFO] [stdout] 2026-04-19T22:53:48.290145Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.291529Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.291596Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.291635Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:53:48.291716Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56 [INFO] [stdout] 2026-04-19T22:53:48.291757Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56 [INFO] [stdout] 2026-04-19T22:53:48.291821Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56 [INFO] [stdout] 2026-04-19T22:53:48.291900Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.291936Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.292009Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.292044Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.292098Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.292158Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.292199Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.292258Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.292294Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.292354Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.292391Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.293874Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.293949Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.294000Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.294076Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.294116Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.294189Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.294223Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.294278Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.295860Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.295933Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.295979Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.296052Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.296087Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.296148Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.296185Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.296256Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.296314Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.296347Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.296441Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.296551Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.296635Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:53:48.296693Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56 [INFO] [stdout] 2026-04-19T22:53:48.296728Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.296823Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.296941Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.297048Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:53:48.297140Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.297228Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2026-04-19T22:53:48.297293Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95 [INFO] [stdout] 2026-04-19T22:53:48.297364Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111 [INFO] [stdout] 2026-04-19T22:53:48.297427Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57 [INFO] [stdout] 2026-04-19T22:53:48.297486Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2026-04-19T22:53:48.297528Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72 [INFO] [stdout] 2026-04-19T22:53:48.297610Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72 [INFO] [stdout] 2026-04-19T22:53:48.297656Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72 [INFO] [stdout] 2026-04-19T22:53:48.298021Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72 [INFO] [stdout] 2026-04-19T22:53:48.300928Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111 [INFO] [stdout] 2026-04-19T22:53:48.301074Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95 [INFO] [stdout] 2026-04-19T22:53:48.301192Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.301311Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.301412Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.301518Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.301636Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.301726Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.301850Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.301936Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.302074Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.302175Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.302287Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.302452Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.302568Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.302706Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.302808Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.302957Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.303064Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.303202Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.303331Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.303452Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.303555Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.303653Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.303777Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.303911Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.304045Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.304146Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.304262Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.304415Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.310409Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.310653Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.311230Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.311409Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.311561Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.311745Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.311946Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.312271Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.312405Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.312706Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.312882Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.312902Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.313044Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.313089Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.313104Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.313114Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.313125Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.313138Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:53:48.313170Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:53:48.313182Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:53:48.313197Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=72 [INFO] [stdout] 2026-04-19T22:53:48.313209Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.313223Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.313259Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:53:48.313273Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:53:48.313288Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=76 [INFO] [stdout] 2026-04-19T22:53:48.313305Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=76 [INFO] [stdout] 2026-04-19T22:53:48.313342Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=27 future=76 [INFO] [stdout] 2026-04-19T22:53:48.313361Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=27 future=76 [INFO] [stdout] 2026-04-19T22:53:48.313377Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=21 future=91 [INFO] [stdout] 2026-04-19T22:53:48.313393Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=21 future=91 [INFO] [stdout] 2026-04-19T22:53:48.313432Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=95 future=106 [INFO] [stdout] 2026-04-19T22:53:48.313449Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=57 future=106 [INFO] [stdout] 2026-04-19T22:53:48.313469Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=78 [INFO] [stdout] 2026-04-19T22:53:48.313486Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=78 [INFO] [stdout] 2026-04-19T22:53:48.313524Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=23 future=97 [INFO] [stdout] 2026-04-19T22:53:48.313541Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=23 future=97 [INFO] [stdout] 2026-04-19T22:53:48.313558Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=95 future=106 [INFO] [stdout] 2026-04-19T22:53:48.313598Z 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-19T22:53:48.313616Z 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] test test::test_memory_read_and_write ... 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] Failed to init tracing: a global default trace dispatcher has already been set [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: 0x63d6ba7a3dba - std[31e582c13f4e914f]::backtrace_rs::backtrace::libunwind::trace [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/../../backtrace/src/backtrace/libunwind.rs:117:9 [INFO] [stdout] 1: 0x63d6ba7a3dba - std[31e582c13f4e914f]::backtrace_rs::backtrace::trace_unsynchronized:: [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/../../backtrace/src/backtrace/mod.rs:66:14 [INFO] [stdout] 2: 0x63d6ba7a3dba - std[31e582c13f4e914f]::sys::backtrace::_print_fmt [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/sys/backtrace.rs:74:9 [INFO] [stdout] 3: 0x63d6ba7a3dba - <::print::DisplayBacktrace as core[fa0eadad68403074]::fmt::Display>::fmt [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/sys/backtrace.rs:44:26 [INFO] [stdout] 4: 0x63d6ba7b911a - ::fmt [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/core/src/fmt/rt.rs:152:76 [INFO] [stdout] 5: 0x63d6ba7b911a - core[fa0eadad68403074]::fmt::write [INFO] [stdout] 6: 0x63d6ba7a86f2 - std[31e582c13f4e914f]::io::default_write_fmt::> [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/io/mod.rs:639:11 [INFO] [stdout] 7: 0x63d6ba7a86f2 - as std[31e582c13f4e914f]::io::Write>::write_fmt [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/io/mod.rs:1994:13 [INFO] [stdout] 8: 0x63d6ba782e1f - ::print [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/sys/backtrace.rs:47:9 [INFO] [stdout] 9: 0x63d6ba782e1f - std[31e582c13f4e914f]::panicking::default_hook::{closure#0} [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/panicking.rs:292:27 [INFO] [stdout] 10: 0x63d6ba79c1a9 - std[31e582c13f4e914f]::panicking::default_hook [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/panicking.rs:316:9 [INFO] [stdout] 11: 0x63d6ba59cc1c - core[fa0eadad68403074]::ops::function::Fn<(&'a std[31e582c13f4e914f]::panic::PanicHookInfo<'b>,), Output = ()> + core[fa0eadad68403074]::marker::Sync + core[fa0eadad68403074]::marker::Send> as core[fa0eadad68403074]::ops::function::Fn<(&std[31e582c13f4e914f]::panic::PanicHookInfo,)>>::call [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/alloc/src/boxed.rs:2254:9 [INFO] [stdout] 12: 0x63d6ba59cc1c - test[7530e63dc052480e]::test_main_with_exit_callback::::{closure#0} [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/test/src/lib.rs:145:21 [INFO] [stdout] 13: 0x63d6ba79c362 - core[fa0eadad68403074]::ops::function::Fn<(&'a std[31e582c13f4e914f]::panic::PanicHookInfo<'b>,), Output = ()> + core[fa0eadad68403074]::marker::Sync + core[fa0eadad68403074]::marker::Send> as core[fa0eadad68403074]::ops::function::Fn<(&std[31e582c13f4e914f]::panic::PanicHookInfo,)>>::call [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/alloc/src/boxed.rs:2254:9 [INFO] [stdout] 14: 0x63d6ba79c362 - std[31e582c13f4e914f]::panicking::panic_with_hook [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/panicking.rs:833:13 [INFO] [stdout] 15: 0x63d6ba782f0a - std[31e582c13f4e914f]::panicking::panic_handler::{closure#0} [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/panicking.rs:691:13 [INFO] [stdout] 16: 0x63d6ba7780b9 - std[31e582c13f4e914f]::sys::backtrace::__rust_end_short_backtrace:: [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/sys/backtrace.rs:182:18 [INFO] [stdout] 17: 0x63d6ba783bed - __rustc[fc8e3a9f23f26cb]::rust_begin_unwind [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/panicking.rs:689:5 [INFO] [stdout] 18: 0x63d6ba7b995c - core[fa0eadad68403074]::panicking::panic_fmt [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/core/src/panicking.rs:80:14 [INFO] [stdout] 19: 0x63d6ba7b9922 - core[fa0eadad68403074]::panicking::panic [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/core/src/panicking.rs:150:5 [INFO] [stdout] 20: 0x63d6ba5816bf - ramu_rs[814fb5cb85c94f8e]::controller::tests::test_controller_simple_read [INFO] [stdout] at /opt/rustwide/workdir/src/controller.rs:300:9 [INFO] [stdout] 21: 0x63d6ba57f337 - ramu_rs[814fb5cb85c94f8e]::controller::tests::test_controller_simple_read::{closure#0} [INFO] [stdout] at /opt/rustwide/workdir/src/controller.rs:277:37 [INFO] [stdout] 22: 0x63d6ba588346 - >::call_once [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/core/src/ops/function.rs:250:5 [INFO] [stdout] 23: 0x63d6ba590cfb - core[fa0eadad68403074]::result::Result<(), alloc[49b8922c36ca62de]::string::String> as core[fa0eadad68403074]::ops::function::FnOnce<()>>::call_once [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/core/src/ops/function.rs:250:5 [INFO] [stdout] 24: 0x63d6ba590cfb - test[7530e63dc052480e]::__rust_begin_short_backtrace::, fn() -> core[fa0eadad68403074]::result::Result<(), alloc[49b8922c36ca62de]::string::String>> [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/test/src/lib.rs:663:18 [INFO] [stdout] 25: 0x63d6ba59d6eb - test[7530e63dc052480e]::run_test_in_process::{closure#0} [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/test/src/lib.rs:686:74 [INFO] [stdout] 26: 0x63d6ba59d6eb - as core[fa0eadad68403074]::ops::function::FnOnce<()>>::call_once [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/core/src/panic/unwind_safe.rs:275:9 [INFO] [stdout] 27: 0x63d6ba59d6eb - std[31e582c13f4e914f]::panicking::catch_unwind::do_call::, core[fa0eadad68403074]::result::Result<(), alloc[49b8922c36ca62de]::string::String>> [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/panicking.rs:581:40 [INFO] [stdout] 28: 0x63d6ba59d6eb - std[31e582c13f4e914f]::panicking::catch_unwind::, core[fa0eadad68403074]::panic::unwind_safe::AssertUnwindSafe> [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/panicking.rs:544:19 [INFO] [stdout] 29: 0x63d6ba59d6eb - std[31e582c13f4e914f]::panic::catch_unwind::, core[fa0eadad68403074]::result::Result<(), alloc[49b8922c36ca62de]::string::String>> [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/panic.rs:359:14 [INFO] [stdout] 30: 0x63d6ba59d6eb - test[7530e63dc052480e]::run_test_in_process [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/test/src/lib.rs:686:27 [INFO] [stdout] 31: 0x63d6ba59d6eb - test[7530e63dc052480e]::run_test::{closure#0} [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/test/src/lib.rs:607:43 [INFO] [stdout] 32: 0x63d6ba597b44 - test[7530e63dc052480e]::run_test::{closure#1} [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/test/src/lib.rs:637:41 [INFO] [stdout] 33: 0x63d6ba597b44 - std[31e582c13f4e914f]::sys::backtrace::__rust_begin_short_backtrace:: [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/sys/backtrace.rs:166:18 [INFO] [stdout] 34: 0x63d6ba5a02f2 - std[31e582c13f4e914f]::thread::lifecycle::spawn_unchecked::::{closure#1}::{closure#0} [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/thread/lifecycle.rs:91:13 [INFO] [stdout] 35: 0x63d6ba5a02f2 - ::{closure#1}::{closure#0}> as core[fa0eadad68403074]::ops::function::FnOnce<()>>::call_once [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/core/src/panic/unwind_safe.rs:275:9 [INFO] [stdout] 36: 0x63d6ba5a02f2 - std[31e582c13f4e914f]::panicking::catch_unwind::do_call::::{closure#1}::{closure#0}>, ()> [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/panicking.rs:581:40 [INFO] [stdout] 37: 0x63d6ba5a02f2 - std[31e582c13f4e914f]::panicking::catch_unwind::<(), core[fa0eadad68403074]::panic::unwind_safe::AssertUnwindSafe::{closure#1}::{closure#0}>> [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/panicking.rs:544:19 [INFO] [stdout] 38: 0x63d6ba5a02f2 - std[31e582c13f4e914f]::panic::catch_unwind::::{closure#1}::{closure#0}>, ()> [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/panic.rs:359:14 [INFO] [stdout] 39: 0x63d6ba5a02f2 - std[31e582c13f4e914f]::thread::lifecycle::spawn_unchecked::::{closure#1} [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/thread/lifecycle.rs:89:26 [INFO] [stdout] 40: 0x63d6ba5a02f2 - ::{closure#1} as core[fa0eadad68403074]::ops::function::FnOnce<()>>::call_once::{shim:vtable#0} [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/core/src/ops/function.rs:250:5 [INFO] [stdout] 41: 0x63d6ba7a369f - + core[fa0eadad68403074]::marker::Send> as core[fa0eadad68403074]::ops::function::FnOnce<()>>::call_once [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/alloc/src/boxed.rs:2240:9 [INFO] [stdout] 42: 0x63d6ba7a369f - ::new::thread_start [INFO] [stdout] at /rustc/562dee4820c458d823175268e41601d4c060588a/library/std/src/sys/thread/unix.rs:118:17 [INFO] [stdout] 43: 0x770f9b632aa4 - [INFO] [stdout] 44: 0x770f9b6bfa64 - 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.09s [INFO] [stdout] [INFO] [stderr] error: test failed, to rerun pass `--lib` [INFO] running `Command { std: "docker" "inspect" "bd67600bb0d5dd2beb6adbd799b685a43d5163fc2a185f194c7154dd8dcbe41c", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "bd67600bb0d5dd2beb6adbd799b685a43d5163fc2a185f194c7154dd8dcbe41c", kill_on_drop: false }` [INFO] [stdout] bd67600bb0d5dd2beb6adbd799b685a43d5163fc2a185f194c7154dd8dcbe41c