[INFO] fetching crate ramu_rs 0.1.1... [INFO] testing ramu_rs-0.1.1 against try#dec9417b8611e34e787a3e4c37686b5131f9e5c5 for pr-154210-2 [INFO] extracting crate ramu_rs 0.1.1 into /workspace/builds/worker-5-tc2/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-tc2/source/Cargo.toml [INFO] validating manifest of crates.io crate ramu_rs 0.1.1 on toolchain dec9417b8611e34e787a3e4c37686b5131f9e5c5 [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+dec9417b8611e34e787a3e4c37686b5131f9e5c5" "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" "+dec9417b8611e34e787a3e4c37686b5131f9e5c5" "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" "+dec9417b8611e34e787a3e4c37686b5131f9e5c5" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] [stderr] Blocking waiting for file lock on package cache [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/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" "+dec9417b8611e34e787a3e4c37686b5131f9e5c5" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }` [INFO] [stdout] 8ab61ab10ddf300c84e97b249c4047bb097c571fee5d60d798645e48bd249ff5 [INFO] running `Command { std: "docker" "start" "-a" "8ab61ab10ddf300c84e97b249c4047bb097c571fee5d60d798645e48bd249ff5", kill_on_drop: false }` [INFO] running `Command { std: "docker" "inspect" "8ab61ab10ddf300c84e97b249c4047bb097c571fee5d60d798645e48bd249ff5", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "8ab61ab10ddf300c84e97b249c4047bb097c571fee5d60d798645e48bd249ff5", kill_on_drop: false }` [INFO] [stdout] 8ab61ab10ddf300c84e97b249c4047bb097c571fee5d60d798645e48bd249ff5 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/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" "+dec9417b8611e34e787a3e4c37686b5131f9e5c5" "build" "--frozen" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 22f296a1d64345155fb578793b5825ef7b25bd15ca68a83cfaf17e7759d011ba [INFO] running `Command { std: "docker" "start" "-a" "22f296a1d64345155fb578793b5825ef7b25bd15ca68a83cfaf17e7759d011ba", kill_on_drop: false }` [INFO] [stderr] Compiling hashbrown v0.17.0 [INFO] [stderr] Compiling equivalent v1.0.2 [INFO] [stderr] Compiling syn v1.0.109 [INFO] [stderr] Compiling toml_datetime v0.6.11 [INFO] [stderr] Compiling link-cplusplus v1.0.12 [INFO] [stderr] Compiling winnow v0.5.40 [INFO] [stderr] Compiling syn v2.0.117 [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 45.68s [INFO] running `Command { std: "docker" "inspect" "22f296a1d64345155fb578793b5825ef7b25bd15ca68a83cfaf17e7759d011ba", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "22f296a1d64345155fb578793b5825ef7b25bd15ca68a83cfaf17e7759d011ba", kill_on_drop: false }` [INFO] [stdout] 22f296a1d64345155fb578793b5825ef7b25bd15ca68a83cfaf17e7759d011ba [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/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" "+dec9417b8611e34e787a3e4c37686b5131f9e5c5" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 19ed519d49d4d464c7bb6e018f5993ebc52309761b31f3711765491ee4eab67a [INFO] running `Command { std: "docker" "start" "-a" "19ed519d49d4d464c7bb6e018f5993ebc52309761b31f3711765491ee4eab67a", kill_on_drop: false }` [INFO] [stderr] Compiling ramu_rs v0.1.1 (/opt/rustwide/workdir) [INFO] [stderr] Finished `test` profile [unoptimized + debuginfo] target(s) in 2.29s [INFO] running `Command { std: "docker" "inspect" "19ed519d49d4d464c7bb6e018f5993ebc52309761b31f3711765491ee4eab67a", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "19ed519d49d4d464c7bb6e018f5993ebc52309761b31f3711765491ee4eab67a", kill_on_drop: false }` [INFO] [stdout] 19ed519d49d4d464c7bb6e018f5993ebc52309761b31f3711765491ee4eab67a [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/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" "+dec9417b8611e34e787a3e4c37686b5131f9e5c5" "test" "--frozen", kill_on_drop: false }` [INFO] [stdout] 91e97f7bfd95321595c4eeb32ac92d699acc8609324f00c566eb53575f9c0086 [INFO] running `Command { std: "docker" "start" "-a" "91e97f7bfd95321595c4eeb32ac92d699acc8609324f00c566eb53575f9c0086", kill_on_drop: false }` [INFO] [stderr] Finished `test` profile [unoptimized + debuginfo] target(s) in 0.14s [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] test scheduler::tests::test ... ok [INFO] [stdout] 2026-04-19T22:54:40.342365Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2026-04-19T22:54:40.342406Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2026-04-19T22:54:40.342423Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2026-04-19T22:54:40.342435Z  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:54:40.342479Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342495Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342510Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342527Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2026-04-19T22:54:40.342523Z  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:54:40.342538Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2026-04-19T22:54:40.342541Z  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:54:40.342550Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2026-04-19T22:54:40.342557Z  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:54:40.342561Z  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:54:40.342573Z  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:54:40.342589Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342594Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342602Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342608Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342615Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342621Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342630Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342633Z  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:54:40.342643Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342649Z  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:54:40.342656Z  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:54:40.342665Z  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:54:40.342676Z  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:54:40.342681Z  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:54:40.342696Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342692Z  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:54:40.342709Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342710Z  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:54:40.342721Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342743Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342741Z  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:54:40.342755Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342768Z  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:54:40.342765Z  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:54:40.342787Z  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:54:40.342794Z  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:54:40.342803Z  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:54:40.342820Z  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:54:40.342820Z  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:54:40.342852Z  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:54:40.342864Z  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:54:40.342866Z  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:54:40.342892Z  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:54:40.342888Z  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:54:40.342906Z  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:54:40.342925Z  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:54:40.342919Z  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:54:40.342939Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342943Z  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:54:40.342952Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.342961Z  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:54:40.342964Z  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:54:40.342975Z  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:54:40.342984Z  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:54:40.343003Z  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:54:40.343004Z  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:54:40.343017Z  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:54:40.343019Z  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:54:40.343036Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343036Z  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:54:40.343049Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343050Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343061Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343062Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343074Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343075Z  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:54:40.343087Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343089Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2026-04-19T22:54:40.343091Z  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:54:40.343108Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2026-04-19T22:54:40.343100Z  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:54:40.343110Z  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:54:40.343121Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2026-04-19T22:54:40.343122Z  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:54:40.343125Z  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:54:40.343136Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343132Z  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:54:40.343143Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343149Z  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:54:40.343156Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343162Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343163Z  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:54:40.343169Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343178Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343179Z  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:54:40.343182Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343191Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343194Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343193Z  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:54:40.343208Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343206Z  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:54:40.343207Z  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:54:40.343220Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343224Z  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:54:40.343228Z  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:54:40.343232Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343242Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343240Z  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:54:40.343245Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343255Z  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:54:40.343260Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343259Z  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:54:40.343269Z  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:54:40.343273Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343277Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343285Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343284Z  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:54:40.343291Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343298Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343299Z  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:54:40.343306Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343311Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343313Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343320Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343324Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343325Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343335Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343337Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343354Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343369Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343363Z  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:54:40.343383Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343387Z  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:54:40.343441Z  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:54:40.343397Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343336Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343508Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343492Z  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:54:40.343516Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343527Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343532Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343529Z  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:54:40.343540Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343545Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343554Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343558Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343567Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343553Z  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:54:40.343580Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343570Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343593Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343602Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343606Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343596Z  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:54:40.343616Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343619Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343623Z  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:54:40.343629Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343632Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343641Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343640Z  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:54:40.343645Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343654Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343657Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343655Z  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:54:40.343669Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343682Z  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:54:40.343691Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343697Z  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:54:40.343744Z  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:54:40.343670Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343795Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343706Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343813Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2026-04-19T22:54:40.343814Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343825Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2026-04-19T22:54:40.343823Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343827Z  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:54:40.343851Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2026-04-19T22:54:40.343857Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343858Z  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:54:40.343862Z  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:54:40.343871Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343876Z  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:54:40.343885Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343893Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343893Z  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:54:40.343898Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343906Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343911Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343919Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2026-04-19T22:54:40.343921Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343924Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343937Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343934Z  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:54:40.343949Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343950Z  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:54:40.343968Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.343966Z  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:54:40.343982Z  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:54:40.343981Z  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:54:40.343997Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344002Z  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:54:40.344009Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344016Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344022Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344028Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.344029Z  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:54:40.344036Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344048Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.344047Z  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:54:40.344048Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344065Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=0 [INFO] [stdout] 2026-04-19T22:54:40.344080Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.344077Z  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:54:40.344095Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.344101Z  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:54:40.344109Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.344119Z  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:54:40.344124Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.344142Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.344138Z  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:54:40.344155Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=0 [INFO] [stdout] 2026-04-19T22:54:40.344174Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=39 [INFO] [stdout] 2026-04-19T22:54:40.344173Z  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:54:40.344192Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=55 [INFO] [stdout] 2026-04-19T22:54:40.344210Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=1 [INFO] [stdout] 2026-04-19T22:54:40.344199Z  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:54:40.344228Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=0 [INFO] [stdout] 2026-04-19T22:54:40.344232Z  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:54:40.344247Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=16 [INFO] [stdout] 2026-04-19T22:54:40.344261Z  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:54:40.344266Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=16 [INFO] [stdout] 2026-04-19T22:54:40.344282Z  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:54:40.344283Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=16 [INFO] [stdout] 2026-04-19T22:54:40.344301Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=16 [INFO] [stdout] 2026-04-19T22:54:40.344298Z  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:54:40.344317Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=55 [INFO] [stdout] 2026-04-19T22:54:40.344328Z  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:54:40.344333Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=39 [INFO] [stdout] 2026-04-19T22:54:40.344353Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.344345Z  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:54:40.344371Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.344369Z  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:54:40.344384Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.344387Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344397Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.344402Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344407Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.344419Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.344417Z  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:54:40.344431Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.344434Z  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:54:40.344442Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.344454Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.344453Z  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:54:40.344466Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.344477Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.344470Z  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:54:40.344488Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.344491Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344501Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.344511Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.344508Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344523Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.344525Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344535Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.344540Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344545Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.344554Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344557Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.344571Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.344570Z  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:54:40.344581Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.344594Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.344593Z  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:54:40.344606Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.344611Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344616Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.344628Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.344626Z  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:54:40.344640Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.344643Z  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:54:40.344650Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.344664Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.344662Z  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:54:40.344677Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.344679Z  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:54:40.344688Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.344696Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344700Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.344714Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.344711Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344725Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.344727Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344738Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.344741Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344751Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.344757Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344762Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.344774Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.344772Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344787Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.344788Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344797Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.344803Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344810Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.344818Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344824Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.344850Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344856Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.344870Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.344867Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344883Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.344884Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344893Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.344899Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344905Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.344914Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344918Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.344930Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.344929Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344943Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.344945Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344957Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=16 [INFO] [stdout] 2026-04-19T22:54:40.344959Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344969Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.344982Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.344990Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.344997Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.345005Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.345012Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.345021Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.345028Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.345037Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=20 [INFO] [stdout] 2026-04-19T22:54:40.345043Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.345055Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=20 [INFO] [stdout] 2026-04-19T22:54:40.345058Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.345073Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.345072Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=20 [INFO] [stdout] 2026-04-19T22:54:40.345088Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.345089Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=20 [INFO] [stdout] 2026-04-19T22:54:40.345103Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.345107Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=26 [INFO] [stdout] 2026-04-19T22:54:40.345119Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.345123Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=26 [INFO] [stdout] 2026-04-19T22:54:40.345134Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.345140Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=39 future=25 [INFO] [stdout] 2026-04-19T22:54:40.345149Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.345157Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=1 future=37 [INFO] [stdout] 2026-04-19T22:54:40.345164Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2026-04-19T22:54:40.345178Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=22 [INFO] [stdout] 2026-04-19T22:54:40.345196Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=22 [INFO] [stdout] 2026-04-19T22:54:40.345214Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=39 future=25 [INFO] [stdout] 2026-04-19T22:54:40.345240Z 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:54:40.345253Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2026-04-19T22:54:40.345273Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.345286Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.345301Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2026-04-19T22:54:40.345315Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.345330Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.345346Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.345361Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.345377Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.345389Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2026-04-19T22:54:40.345408Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2026-04-19T22:54:40.345427Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2026-04-19T22:54:40.345446Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2026-04-19T22:54:40.345466Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2026-04-19T22:54:40.345485Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2026-04-19T22:54:40.345506Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2026-04-19T22:54:40.345525Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2026-04-19T22:54:40.345544Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2026-04-19T22:54:40.345564Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2026-04-19T22:54:40.345583Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2026-04-19T22:54:40.345605Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.345617Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.345630Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.345644Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.345655Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.345669Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.345683Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.345694Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.345717Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.345733Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.345744Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.345757Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.345771Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.345781Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.345794Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.345808Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.346920Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.346947Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.346962Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.346983Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.346996Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.347009Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.347022Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.347035Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.347049Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.347062Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2026-04-19T22:54:40.347143Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2026-04-19T22:54:40.347162Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.347174Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.347188Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2026-04-19T22:54:40.347201Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.347215Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.347229Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.347242Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.347257Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.347268Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2026-04-19T22:54:40.347286Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2026-04-19T22:54:40.347304Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2026-04-19T22:54:40.347323Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2026-04-19T22:54:40.347343Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2026-04-19T22:54:40.347362Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2026-04-19T22:54:40.347379Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2026-04-19T22:54:40.347396Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2026-04-19T22:54:40.347412Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2026-04-19T22:54:40.347429Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2026-04-19T22:54:40.347445Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2026-04-19T22:54:40.347465Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.347476Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.347488Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.347500Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.347510Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.347521Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.347534Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.347545Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.347557Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.347570Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.347580Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.347591Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.347604Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.347614Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.347625Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.347637Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.347649Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.347660Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.347672Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.347682Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.347694Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.347706Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.347717Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.347729Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.347743Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.347754Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.347767Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.347780Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.347791Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.347803Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.347816Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.347827Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.347857Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.347870Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.347863Z  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:54:40.347880Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.347893Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.347889Z  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:54:40.347905Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.347907Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.347915Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.347920Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.347926Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.347939Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.347937Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.347948Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.347959Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.347953Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.347971Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.347976Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.347987Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.347992Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.347998Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.348011Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.348007Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348020Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.348022Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348031Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.348037Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348044Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.348053Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.348051Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348064Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.348066Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348076Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.348081Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348085Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.348096Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348098Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.348111Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.348110Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348121Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.348125Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348132Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.348140Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348144Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.348154Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348155Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.348168Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.348167Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348179Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.348181Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348189Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.348194Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348200Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.348208Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348212Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.348222Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.348221Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348233Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.348235Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348245Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.348248Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348256Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.348262Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348268Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.348280Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.348276Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348289Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.348291Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348301Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.348305Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348313Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.348323Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.348320Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.348334Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.348336Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2026-04-19T22:54:40.348346Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.348356Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.348367Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.348379Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.348389Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.348400Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.348412Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.348422Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.348433Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.348423Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=1 [INFO] [stdout] 2026-04-19T22:54:40.348445Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.348456Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.348455Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 0] [INFO] [stdout] 2026-04-19T22:54:40.348467Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.348479Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.348478Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 0 [INFO] [stdout] 2026-04-19T22:54:40.348489Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.348496Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=65 [INFO] [stdout] 2026-04-19T22:54:40.348501Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.348515Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.348518Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 1] [INFO] [stdout] 2026-04-19T22:54:40.348525Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.348536Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.348538Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 64 [INFO] [stdout] 2026-04-19T22:54:40.348549Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17 [INFO] [stdout] 2026-04-19T22:54:40.348556Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=257 [INFO] [stdout] 2026-04-19T22:54:40.348561Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.348575Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.348575Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 4] [INFO] [stdout] 2026-04-19T22:54:40.348588Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.348596Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 256 [INFO] [stdout] 2026-04-19T22:54:40.348601Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.348615Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2026-04-19T22:54:40.348633Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2026-04-19T22:54:40.348649Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2026-04-19T22:54:40.348673Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2026-04-19T22:54:40.348692Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27 [INFO] [stdout] 2026-04-19T22:54:40.348708Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27 [INFO] [stdout] 2026-04-19T22:54:40.348724Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26 [INFO] [stdout] 2026-04-19T22:54:40.348742Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38 [INFO] [stdout] 2026-04-19T22:54:40.348758Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23 [INFO] [stdout] 2026-04-19T22:54:40.348775Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23 [INFO] [stdout] 2026-04-19T22:54:40.348791Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26 [INFO] [stdout] 2026-04-19T22:54:40.348809Z 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:54:40.348828Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.348853Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.348865Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.348877Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.348887Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.348898Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.348911Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.348921Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.348932Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.348944Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.348953Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.348965Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.348983Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.348993Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349005Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349017Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349026Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349038Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349050Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349059Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349071Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349083Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349092Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349104Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349115Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349125Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349137Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349149Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349159Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349170Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349182Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349193Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349205Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349217Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349226Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349238Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349251Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349260Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349271Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349283Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349294Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349305Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349318Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349328Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349340Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349352Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349361Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349373Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349385Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349394Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349406Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349417Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349427Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349439Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349451Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349460Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349472Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349484Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349494Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349506Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349524Z 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:54:40.349537Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349547Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349559Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349571Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349580Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349592Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349603Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349613Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349651Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349663Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40 [INFO] [stdout] 2026-04-19T22:54:40.349674Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.349688Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.349702Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.349715Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:54:40.349729Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56 [INFO] [stdout] 2026-04-19T22:54:40.349746Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56 [INFO] [stdout] 2026-04-19T22:54:40.349763Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56 [INFO] [stdout] 2026-04-19T22:54:40.349781Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349791Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.349803Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349813Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.349825Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349851Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.345825Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349864Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349874Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.349873Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] test utils::tests::test_addr ... ok2026-04-19T22:54:40.349886Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] [INFO] [stdout] test ddr4::tests::test_address ... ok [INFO] [stdout] 2026-04-19T22:54:40.349893Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349896Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.349906Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.349908Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349918Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.349920Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.349932Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349933Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349942Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.349944Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.349957Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349954Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.349966Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2026-04-19T22:54:40.349966Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.349974Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349983Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.349982Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2026-04-19T22:54:40.349984Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.349992Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.349995Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2026-04-19T22:54:40.349995Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.350004Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350007Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350013Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.350006Z  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:54:40.350016Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350024Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350028Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.350034Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.350040Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350040Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350045Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350049Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.350056Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.350055Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350061Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.350067Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350068Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350072Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350077Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.350083Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350082Z  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:54:40.350089Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350093Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.350099Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.350105Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350098Z  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:54:40.350111Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350114Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.350115Z  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:54:40.350121Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.350125Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.350134Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350137Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350131Z  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:54:40.350143Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.350146Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350149Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350156Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56 [INFO] [stdout] 2026-04-19T22:54:40.350158Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.350162Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350169Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350168Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.350175Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350179Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.350181Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.350190Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.350188Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350194Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.350201Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350202Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350207Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:54:40.350210Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350221Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350222Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.350214Z  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:54:40.350233Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350231Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2026-04-19T22:54:40.350234Z  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:54:40.350244Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.350246Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95 [INFO] [stdout] 2026-04-19T22:54:40.350255Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.350250Z  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:54:40.350266Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350263Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111 [INFO] [stdout] 2026-04-19T22:54:40.350276Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350279Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57 [INFO] [stdout] 2026-04-19T22:54:40.350286Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.350268Z  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:54:40.350298Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350296Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2026-04-19T22:54:40.350307Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.350298Z  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:54:40.350312Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72 [INFO] [stdout] 2026-04-19T22:54:40.350318Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.350330Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350328Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72 [INFO] [stdout] 2026-04-19T22:54:40.350339Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350323Z  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:54:40.350349Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.350345Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72 [INFO] [stdout] 2026-04-19T22:54:40.350361Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350353Z  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:54:40.350362Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72 [INFO] [stdout] 2026-04-19T22:54:40.350371Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.350382Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.350378Z  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:54:40.350452Z  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:54:40.350381Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111 [INFO] [stdout] 2026-04-19T22:54:40.350474Z  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:54:40.350501Z  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:54:40.350505Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95 [INFO] [stdout] 2026-04-19T22:54:40.350515Z  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:54:40.350530Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350533Z  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:54:40.350548Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350540Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350561Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350567Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.350580Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350575Z  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:54:40.350590Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350591Z  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:54:40.350602Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.350614Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350609Z  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:54:40.350626Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350628Z  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:54:40.350637Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.350649Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350647Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350658Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350661Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350669Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.350675Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350681Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350690Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350702Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.350713Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350689Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350723Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350735Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.350733Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350747Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350756Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350748Z  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:54:40.350768Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.350780Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350789Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350771Z  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:54:40.350800Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.350812Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350809Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350822Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350848Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.350824Z  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:54:40.350862Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350872Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350869Z  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:54:40.350884Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.350885Z  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:54:40.350895Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.350900Z  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:54:40.350905Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350913Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350953Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350971Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350985Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.350917Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.351044Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.351056Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.351067Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.351082Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.351005Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351134Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351156Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351171Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351190Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351212Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351231Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351251Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351266Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351286Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351307Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351330Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351350Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351370Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351390Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351405Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351424Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351437Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351450Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351469Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351491Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351510Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351523Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351540Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351554Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2026-04-19T22:54:40.351573Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2026-04-19T22:54:40.351657Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2026-04-19T22:54:40.351684Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.351697Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.351719Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2026-04-19T22:54:40.351739Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.351759Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.351779Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.351793Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.351807Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.351820Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2026-04-19T22:54:40.351863Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2026-04-19T22:54:40.351883Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2026-04-19T22:54:40.351906Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2026-04-19T22:54:40.351930Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2026-04-19T22:54:40.351952Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2026-04-19T22:54:40.351970Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2026-04-19T22:54:40.351991Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2026-04-19T22:54:40.352015Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2026-04-19T22:54:40.352037Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2026-04-19T22:54:40.352059Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2026-04-19T22:54:40.352079Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.352091Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.352112Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.352133Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.352152Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.352170Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.352183Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.352194Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.352213Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.352233Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.352251Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.352269Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.352282Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.352292Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.352306Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.352323Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.352335Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.352352Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.352372Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.352382Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.352394Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.352409Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.352427Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.352446Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.352466Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.352487Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.352500Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.352518Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.352528Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.352541Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.352559Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.352578Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.352596Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.352615Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.352626Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.352638Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.352659Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.352670Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.352687Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.352707Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.352728Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.352741Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.352759Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.352769Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.352786Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.352806Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.352816Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.350393Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.352846Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.352858Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.352864Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.352872Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.352874Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.352884Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.352885Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.352894Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.352942Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.351092Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.352897Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.360879Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.360981Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.360989Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.361003Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.361018Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.361026Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.361029Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.361041Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.361040Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.361052Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.361050Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.361061Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.361062Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.361073Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.361072Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.361084Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.361093Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.361106Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.361001Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.361118Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.361120Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.361127Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.361130Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.361138Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.361141Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.361150Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.361153Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.361160Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.361162Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.361213Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.361229Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.361245Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.361082Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.361299Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.361322Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.361171Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.361373Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.361392Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.361406Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.361448Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.361469Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.361480Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.361497Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.361423Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.361546Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.361559Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.361580Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=17 [INFO] [stdout] 2026-04-19T22:54:40.361334Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.361663Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.361679Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=72 [INFO] [stdout] 2026-04-19T22:54:40.361730Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.361747Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.361784Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.361808Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.361628Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.361867Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.361883Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.361902Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.361941Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.361967Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:54:40.361984Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=76 [INFO] [stdout] 2026-04-19T22:54:40.361824Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.361914Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.362067Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.362091Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.362132Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.362154Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.362195Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=76 [INFO] [stdout] 2026-04-19T22:54:40.362226Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=27 future=76 [INFO] [stdout] 2026-04-19T22:54:40.362250Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=27 future=76 [INFO] [stdout] 2026-04-19T22:54:40.362276Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=21 future=91 [INFO] [stdout] 2026-04-19T22:54:40.362300Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=21 future=91 [INFO] [stdout] 2026-04-19T22:54:40.362324Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=95 future=106 [INFO] [stdout] 2026-04-19T22:54:40.362348Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=57 future=106 [INFO] [stdout] 2026-04-19T22:54:40.362367Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=78 [INFO] [stdout] 2026-04-19T22:54:40.362403Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.362425Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.362456Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=21 [INFO] [stdout] 2026-04-19T22:54:40.362529Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=21 [INFO] [stdout] 2026-04-19T22:54:40.362611Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=0 future=21 [INFO] [stdout] 2026-04-19T22:54:40.362693Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.362815Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.362888Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.362656Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=0 future=21 [INFO] [stdout] 2026-04-19T22:54:40.363007Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=0 future=36 [INFO] [stdout] 2026-04-19T22:54:40.362776Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=78 [INFO] [stdout] 2026-04-19T22:54:40.363160Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=0 future=36 [INFO] [stdout] 2026-04-19T22:54:40.362932Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.363276Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.363381Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.363351Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=40 future=51 [INFO] [stdout] 2026-04-19T22:54:40.363526Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=2 future=51 [INFO] [stdout] 2026-04-19T22:54:40.363119Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=23 future=97 [INFO] [stdout] 2026-04-19T22:54:40.363643Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=23 future=97 [INFO] [stdout] 2026-04-19T22:54:40.363723Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=23 [INFO] [stdout] 2026-04-19T22:54:40.363492Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.363952Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.363897Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=23 [INFO] [stdout] 2026-04-19T22:54:40.364062Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=0 future=42 [INFO] [stdout] 2026-04-19T22:54:40.364158Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=0 future=42 [INFO] [stdout] 2026-04-19T22:54:40.363763Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=95 future=106 [INFO] [stdout] 2026-04-19T22:54:40.364006Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.364331Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.364443Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.364418Z 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:54:40.364589Z DEBUG ramu_rs::test: recv req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 72 } [INFO] [stdout] 2026-04-19T22:54:40.364527Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.364748Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.364391Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=40 future=51 [INFO] [stdout] 2026-04-19T22:54:40.364869Z 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:54:40.365032Z 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:54:40.364935Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.365200Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.365279Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2026-04-19T22:54:40.365247Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.365738Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.365453Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] test test::test_memory_read_and_write ... ok [INFO] [stdout] 2026-04-19T22:54:40.365827Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.366147Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.365906Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17 [INFO] [stdout] 2026-04-19T22:54:40.366266Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.366347Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.366410Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.366324Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.366495Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.366583Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2026-04-19T22:54:40.366537Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.366675Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.366763Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.366704Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2026-04-19T22:54:40.366861Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2026-04-19T22:54:40.366911Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.366979Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.367046Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.367018Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2026-04-19T22:54:40.367150Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27 [INFO] [stdout] 2026-04-19T22:54:40.367127Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.367242Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.367270Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.367215Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27 [INFO] [stdout] 2026-04-19T22:54:40.367360Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26 [INFO] [stdout] 2026-04-19T22:54:40.367401Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.367448Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.367506Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.367478Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38 [INFO] [stdout] 2026-04-19T22:54:40.367593Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23 [INFO] [stdout] 2026-04-19T22:54:40.367572Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.367692Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.368321Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.367664Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23 [INFO] [stdout] test controller::tests::test_controller_simple_read ... FAILED [INFO] [stdout] 2026-04-19T22:54:40.368498Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.368586Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.368649Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.368422Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26 [INFO] [stdout] 2026-04-19T22:54:40.368733Z 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:54:40.368755Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.368765Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.368776Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.368788Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.368797Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.368808Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.368819Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.368828Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.368856Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.368869Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.368878Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.368889Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.368901Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.368910Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.368921Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.368932Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.368942Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.368953Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.368966Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.368977Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.368990Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.369003Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369014Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.369026Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.369039Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369052Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.369064Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.369076Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369087Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.369099Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.369112Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369122Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.369134Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.369148Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369158Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.369171Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.369184Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369193Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.369206Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.369219Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369229Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.369240Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.369253Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369264Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.369276Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.369288Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369298Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.369308Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.369320Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369329Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.369340Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.369352Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369362Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.369375Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.369387Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369397Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.369409Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.369423Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369432Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.369443Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.369463Z 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:54:40.369477Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369488Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.369499Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.369511Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369520Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.369531Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.369544Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369554Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.369564Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.369576Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40 [INFO] [stdout] 2026-04-19T22:54:40.369588Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.369601Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.369614Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.369652Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:54:40.369666Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56 [INFO] [stdout] 2026-04-19T22:54:40.369683Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56 [INFO] [stdout] 2026-04-19T22:54:40.369705Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56 [INFO] [stdout] 2026-04-19T22:54:40.369729Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369741Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.369754Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.369764Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.369778Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.371699Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.371872Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.371892Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.371905Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.371917Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.371926Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.371937Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.371949Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.371959Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.371972Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.372019Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.372030Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.372042Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.372055Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.372064Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.372076Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.372088Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.372098Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.372109Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.372122Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.372132Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.372143Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.372154Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.372164Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.372174Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.372185Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.372196Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.372207Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.372219Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.372230Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.372244Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.372256Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.372267Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.372279Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.372291Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.372301Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.372313Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.372326Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.372336Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.372347Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.372359Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.372370Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.372382Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.372394Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.372405Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.372416Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.373905Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.373928Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.373942Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.373955Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.373965Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.373978Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.373991Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374001Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.374014Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.374026Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374036Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.374048Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.374060Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374070Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.374082Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.374094Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374105Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.374117Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.374130Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374141Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.374153Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.374166Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374176Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.374188Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.374201Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374211Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.374223Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.374236Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374246Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.374260Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.374273Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374284Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.374296Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2026-04-19T22:54:40.374310Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=51 [INFO] [stdout] 2026-04-19T22:54:40.374323Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.374337Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.374351Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.374366Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:54:40.374382Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=67 [INFO] [stdout] 2026-04-19T22:54:40.374399Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=67 [INFO] [stdout] 2026-04-19T22:54:40.374418Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=67 [INFO] [stdout] 2026-04-19T22:54:40.374439Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374449Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.374461Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374471Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.374483Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374493Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.374505Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374515Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.374527Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374536Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.374548Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374558Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.374570Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374581Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.374594Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374603Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.374615Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374625Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.374637Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374647Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.374660Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374670Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.374682Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374692Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.374704Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374725Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.374738Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374748Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.374760Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374769Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.374781Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.374791Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.374804Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=67 [INFO] [stdout] 2026-04-19T22:54:40.374816Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.374829Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.374860Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.374874Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:54:40.374888Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.374899Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=67 [INFO] [stdout] 2026-04-19T22:54:40.374917Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=51 future=106 [INFO] [stdout] 2026-04-19T22:54:40.374934Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=67 future=122 [INFO] [stdout] 2026-04-19T22:54:40.374951Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=51 future=68 [INFO] [stdout] 2026-04-19T22:54:40.374969Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=67 [INFO] [stdout] 2026-04-19T22:54:40.374986Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=83 [INFO] [stdout] 2026-04-19T22:54:40.375003Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=83 [INFO] [stdout] 2026-04-19T22:54:40.375020Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=83 [INFO] [stdout] 2026-04-19T22:54:40.375037Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=83 [INFO] [stdout] 2026-04-19T22:54:40.375053Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=67 future=122 [INFO] [stdout] 2026-04-19T22:54:40.375070Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=51 future=106 [INFO] [stdout] 2026-04-19T22:54:40.375089Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.375099Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.375111Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.375123Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.375132Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.375144Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.375156Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.375166Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.375177Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.375189Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.375199Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.375212Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.375224Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.375234Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.375245Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.375257Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.375267Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.375278Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.375290Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.375300Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.375312Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.375325Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.375335Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.375346Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.375358Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.375367Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.375378Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.375390Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.375399Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.375411Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.375424Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.375435Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.375447Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.375459Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.375469Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.375481Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.375494Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.375504Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.375515Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.375529Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.375540Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.375552Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.375565Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.375575Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.375586Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.375598Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2026-04-19T22:54:40.375607Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.375618Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2026-04-19T22:54:40.375632Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=83 [INFO] [stdout] 2026-04-19T22:54:40.375644Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.375658Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.375671Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.375684Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:54:40.375699Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=21 future=87 [INFO] [stdout] 2026-04-19T22:54:40.375726Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=21 future=87 [INFO] [stdout] 2026-04-19T22:54:40.375745Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=21 future=87 [INFO] [stdout] 2026-04-19T22:54:40.375763Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=21 future=87 [INFO] [stdout] 2026-04-19T22:54:40.375780Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=36 future=102 [INFO] [stdout] 2026-04-19T22:54:40.375797Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=36 future=102 [INFO] [stdout] 2026-04-19T22:54:40.375815Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=106 future=117 [INFO] [stdout] 2026-04-19T22:54:40.369788Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.379306Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.379443Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.379670Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.379867Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.380079Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.380283Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.380491Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.380623Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.380857Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.381062Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.381269Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.381473Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.381531Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.381708Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.381933Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.382057Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.382291Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.382395Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.383787Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.383824Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.383904Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.383971Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.384006Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.384056Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.384146Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.384226Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2026-04-19T22:54:40.384297Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56 [INFO] [stdout] 2026-04-19T22:54:40.384334Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.384404Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.384443Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.384497Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:54:40.384536Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.384590Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2026-04-19T22:54:40.384666Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95 [INFO] [stdout] 2026-04-19T22:54:40.384707Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111 [INFO] [stdout] 2026-04-19T22:54:40.384788Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57 [INFO] [stdout] 2026-04-19T22:54:40.384827Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2026-04-19T22:54:40.384917Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72 [INFO] [stdout] 2026-04-19T22:54:40.384960Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72 [INFO] [stdout] 2026-04-19T22:54:40.385043Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72 [INFO] [stdout] 2026-04-19T22:54:40.385090Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72 [INFO] [stdout] 2026-04-19T22:54:40.385175Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111 [INFO] [stdout] 2026-04-19T22:54:40.385261Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95 [INFO] [stdout] 2026-04-19T22:54:40.385424Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.385490Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.385576Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.385733Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.385789Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.386899Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.375832Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=68 future=117 [INFO] [stdout] 2026-04-19T22:54:40.387045Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=23 future=89 [INFO] [stdout] 2026-04-19T22:54:40.387112Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.387200Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.387297Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.387256Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=23 future=89 [INFO] [stdout] 2026-04-19T22:54:40.387405Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=42 future=108 [INFO] [stdout] 2026-04-19T22:54:40.387497Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.387614Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.387664Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.387586Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=42 future=108 [INFO] [stdout] 2026-04-19T22:54:40.387773Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=106 future=117 [INFO] [stdout] 2026-04-19T22:54:40.387752Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.388275Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.388496Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.388463Z 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:54:40.388788Z 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:54:40.388940Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.389170Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.389340Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.389646Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.389790Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.389916Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] test test::test_memory_write ... ok [INFO] [stdout] 2026-04-19T22:54:40.390098Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.390184Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.390311Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.390408Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.390493Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.390607Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.390660Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.390777Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.390951Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.391037Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.391154Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.391206Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.391367Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.391507Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.391697Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.391933Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.392115Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.392292Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stderr] error: test failed, to rerun pass `--lib` [INFO] [stdout] 2026-04-19T22:54:40.392544Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.392703Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.392848Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.393495Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.393686Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.394040Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.394129Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2026-04-19T22:54:40.394814Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2026-04-19T22:54:40.394907Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2026-04-19T22:54:40.394995Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=72 [INFO] [stdout] 2026-04-19T22:54:40.395032Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.395143Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.395181Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2026-04-19T22:54:40.395274Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2026-04-19T22:54:40.395354Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=21 future=76 [INFO] [stdout] 2026-04-19T22:54:40.395443Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=21 future=76 [INFO] [stdout] 2026-04-19T22:54:40.395489Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=21 future=76 [INFO] [stdout] 2026-04-19T22:54:40.395573Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=21 future=76 [INFO] [stdout] 2026-04-19T22:54:40.395711Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=27 future=82 [INFO] [stdout] 2026-04-19T22:54:40.395810Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=27 future=82 [INFO] [stdout] 2026-04-19T22:54:40.395912Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=95 future=81 [INFO] [stdout] 2026-04-19T22:54:40.396095Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=57 future=93 [INFO] [stdout] 2026-04-19T22:54:40.396321Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=23 future=78 [INFO] [stdout] 2026-04-19T22:54:40.396411Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=23 future=78 [INFO] [stdout] 2026-04-19T22:54:40.396566Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=95 future=81 [INFO] [stdout] 2026-04-19T22:54:40.396731Z 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:54:40.396794Z 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] test test::test_memory_diffrent_row ... ok [INFO] [stdout] [INFO] [stdout] failures: [INFO] [stdout] [INFO] [stdout] ---- controller::tests::test_controller_simple_read stdout ---- [INFO] [stdout] [INFO] [stdout] thread 'controller::tests::test_controller_simple_read' (16) panicked at src/controller.rs:300:9: [INFO] [stdout] assertion failed: controller.finished_queue.is_empty() [INFO] [stdout] stack backtrace: [INFO] [stdout] 0: 0x5d5ac0e4825a - std[e72de78501789eb0]::backtrace_rs::backtrace::libunwind::trace [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/../../backtrace/src/backtrace/libunwind.rs:117:9 [INFO] [stdout] 1: 0x5d5ac0e4825a - std[e72de78501789eb0]::backtrace_rs::backtrace::trace_unsynchronized:: [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/../../backtrace/src/backtrace/mod.rs:66:14 [INFO] [stdout] 2: 0x5d5ac0e4825a - std[e72de78501789eb0]::sys::backtrace::_print_fmt [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/sys/backtrace.rs:74:9 [INFO] [stdout] 3: 0x5d5ac0e4825a - <::print::DisplayBacktrace as core[6aaeda2c7ad07a48]::fmt::Display>::fmt [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/sys/backtrace.rs:44:26 [INFO] [stdout] 4: 0x5d5ac0e5d5ba - ::fmt [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/core/src/fmt/rt.rs:152:76 [INFO] [stdout] 5: 0x5d5ac0e5d5ba - core[6aaeda2c7ad07a48]::fmt::write [INFO] [stdout] 6: 0x5d5ac0e4cb92 - std[e72de78501789eb0]::io::default_write_fmt::> [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/io/mod.rs:639:11 [INFO] [stdout] 7: 0x5d5ac0e4cb92 - as std[e72de78501789eb0]::io::Write>::write_fmt [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/io/mod.rs:1994:13 [INFO] [stdout] 8: 0x5d5ac0e272bf - ::print [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/sys/backtrace.rs:47:9 [INFO] [stdout] 9: 0x5d5ac0e272bf - std[e72de78501789eb0]::panicking::default_hook::{closure#0} [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/panicking.rs:292:27 [INFO] [stdout] 10: 0x5d5ac0e40699 - std[e72de78501789eb0]::panicking::default_hook [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/panicking.rs:316:9 [INFO] [stdout] 11: 0x5d5ac0c403ac - core[6aaeda2c7ad07a48]::ops::function::Fn<(&'a std[e72de78501789eb0]::panic::PanicHookInfo<'b>,), Output = ()> + core[6aaeda2c7ad07a48]::marker::Sync + core[6aaeda2c7ad07a48]::marker::Send> as core[6aaeda2c7ad07a48]::ops::function::Fn<(&std[e72de78501789eb0]::panic::PanicHookInfo,)>>::call [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/alloc/src/boxed.rs:2254:9 [INFO] [stdout] 12: 0x5d5ac0c403ac - test[4f12b380f1fb68c5]::test_main_with_exit_callback::::{closure#0} [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/test/src/lib.rs:145:21 [INFO] [stdout] 13: 0x5d5ac0e40852 - core[6aaeda2c7ad07a48]::ops::function::Fn<(&'a std[e72de78501789eb0]::panic::PanicHookInfo<'b>,), Output = ()> + core[6aaeda2c7ad07a48]::marker::Sync + core[6aaeda2c7ad07a48]::marker::Send> as core[6aaeda2c7ad07a48]::ops::function::Fn<(&std[e72de78501789eb0]::panic::PanicHookInfo,)>>::call [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/alloc/src/boxed.rs:2254:9 [INFO] [stdout] 14: 0x5d5ac0e40852 - std[e72de78501789eb0]::panicking::panic_with_hook [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/panicking.rs:833:13 [INFO] [stdout] 15: 0x5d5ac0e273aa - std[e72de78501789eb0]::panicking::panic_handler::{closure#0} [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/panicking.rs:691:13 [INFO] [stdout] 16: 0x5d5ac0e1ece9 - std[e72de78501789eb0]::sys::backtrace::__rust_end_short_backtrace:: [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/sys/backtrace.rs:182:18 [INFO] [stdout] 17: 0x5d5ac0e2808d - __rustc[78a4cf188af856fc]::rust_begin_unwind [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/panicking.rs:689:5 [INFO] [stdout] 18: 0x5d5ac0e5ddfc - core[6aaeda2c7ad07a48]::panicking::panic_fmt [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/core/src/panicking.rs:80:14 [INFO] [stdout] 19: 0x5d5ac0e5ddc2 - core[6aaeda2c7ad07a48]::panicking::panic [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/core/src/panicking.rs:150:5 [INFO] [stdout] 20: 0x5d5ac0c1b7ef - ramu_rs[71d888eea7b9da98]::controller::tests::test_controller_simple_read [INFO] [stdout] at /opt/rustwide/workdir/src/controller.rs:300:9 [INFO] [stdout] 21: 0x5d5ac0c16057 - ramu_rs[71d888eea7b9da98]::controller::tests::test_controller_simple_read::{closure#0} [INFO] [stdout] at /opt/rustwide/workdir/src/controller.rs:277:37 [INFO] [stdout] 22: 0x5d5ac0c1d666 - >::call_once [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/core/src/ops/function.rs:250:5 [INFO] [stdout] 23: 0x5d5ac0c3448b - core[6aaeda2c7ad07a48]::result::Result<(), alloc[28d2dab30c1dc666]::string::String> as core[6aaeda2c7ad07a48]::ops::function::FnOnce<()>>::call_once [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/core/src/ops/function.rs:250:5 [INFO] [stdout] 24: 0x5d5ac0c3448b - test[4f12b380f1fb68c5]::__rust_begin_short_backtrace::, fn() -> core[6aaeda2c7ad07a48]::result::Result<(), alloc[28d2dab30c1dc666]::string::String>> [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/test/src/lib.rs:663:18 [INFO] [stdout] 25: 0x5d5ac0c40e7b - test[4f12b380f1fb68c5]::run_test_in_process::{closure#0} [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/test/src/lib.rs:686:74 [INFO] [stdout] 26: 0x5d5ac0c40e7b - as core[6aaeda2c7ad07a48]::ops::function::FnOnce<()>>::call_once [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/core/src/panic/unwind_safe.rs:275:9 [INFO] [stdout] 27: 0x5d5ac0c40e7b - std[e72de78501789eb0]::panicking::catch_unwind::do_call::, core[6aaeda2c7ad07a48]::result::Result<(), alloc[28d2dab30c1dc666]::string::String>> [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/panicking.rs:581:40 [INFO] [stdout] 28: 0x5d5ac0c40e7b - std[e72de78501789eb0]::panicking::catch_unwind::, core[6aaeda2c7ad07a48]::panic::unwind_safe::AssertUnwindSafe> [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/panicking.rs:544:19 [INFO] [stdout] 29: 0x5d5ac0c40e7b - std[e72de78501789eb0]::panic::catch_unwind::, core[6aaeda2c7ad07a48]::result::Result<(), alloc[28d2dab30c1dc666]::string::String>> [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/panic.rs:359:14 [INFO] [stdout] 30: 0x5d5ac0c40e7b - test[4f12b380f1fb68c5]::run_test_in_process [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/test/src/lib.rs:686:27 [INFO] [stdout] 31: 0x5d5ac0c40e7b - test[4f12b380f1fb68c5]::run_test::{closure#0} [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/test/src/lib.rs:607:43 [INFO] [stdout] 32: 0x5d5ac0c3c594 - test[4f12b380f1fb68c5]::run_test::{closure#1} [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/test/src/lib.rs:637:41 [INFO] [stdout] 33: 0x5d5ac0c3c594 - std[e72de78501789eb0]::sys::backtrace::__rust_begin_short_backtrace:: [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/sys/backtrace.rs:166:18 [INFO] [stdout] 34: 0x5d5ac0c43a82 - std[e72de78501789eb0]::thread::lifecycle::spawn_unchecked::::{closure#1}::{closure#0} [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/thread/lifecycle.rs:91:13 [INFO] [stdout] 35: 0x5d5ac0c43a82 - ::{closure#1}::{closure#0}> as core[6aaeda2c7ad07a48]::ops::function::FnOnce<()>>::call_once [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/core/src/panic/unwind_safe.rs:275:9 [INFO] [stdout] 36: 0x5d5ac0c43a82 - std[e72de78501789eb0]::panicking::catch_unwind::do_call::::{closure#1}::{closure#0}>, ()> [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/panicking.rs:581:40 [INFO] [stdout] 37: 0x5d5ac0c43a82 - std[e72de78501789eb0]::panicking::catch_unwind::<(), core[6aaeda2c7ad07a48]::panic::unwind_safe::AssertUnwindSafe::{closure#1}::{closure#0}>> [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/panicking.rs:544:19 [INFO] [stdout] 38: 0x5d5ac0c43a82 - std[e72de78501789eb0]::panic::catch_unwind::::{closure#1}::{closure#0}>, ()> [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/panic.rs:359:14 [INFO] [stdout] 39: 0x5d5ac0c43a82 - std[e72de78501789eb0]::thread::lifecycle::spawn_unchecked::::{closure#1} [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/thread/lifecycle.rs:89:26 [INFO] [stdout] 40: 0x5d5ac0c43a82 - ::{closure#1} as core[6aaeda2c7ad07a48]::ops::function::FnOnce<()>>::call_once::{shim:vtable#0} [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/core/src/ops/function.rs:250:5 [INFO] [stdout] 41: 0x5d5ac0e47b3f - + core[6aaeda2c7ad07a48]::marker::Send> as core[6aaeda2c7ad07a48]::ops::function::FnOnce<()>>::call_once [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/alloc/src/boxed.rs:2240:9 [INFO] [stdout] 42: 0x5d5ac0e47b3f - ::new::thread_start [INFO] [stdout] at /rustc/dec9417b8611e34e787a3e4c37686b5131f9e5c5/library/std/src/sys/thread/unix.rs:118:17 [INFO] [stdout] 43: 0x756513915aa4 - [INFO] [stdout] 44: 0x7565139a2a64 - 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.06s [INFO] [stdout] [INFO] running `Command { std: "docker" "inspect" "91e97f7bfd95321595c4eeb32ac92d699acc8609324f00c566eb53575f9c0086", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "91e97f7bfd95321595c4eeb32ac92d699acc8609324f00c566eb53575f9c0086", kill_on_drop: false }` [INFO] [stdout] 91e97f7bfd95321595c4eeb32ac92d699acc8609324f00c566eb53575f9c0086