[INFO] fetching crate ramu_rs 0.1.1... [INFO] testing ramu_rs-0.1.1 against master#caccb4d0368bd918ef6668af8e13834d07040417 for pr-146098-1 [INFO] extracting crate ramu_rs 0.1.1 into /workspace/builds/worker-2-tc1/source [INFO] started tweaking crates.io crate ramu_rs 0.1.1 [INFO] finished tweaking crates.io crate ramu_rs 0.1.1 [INFO] tweaked toml for crates.io crate ramu_rs 0.1.1 written to /workspace/builds/worker-2-tc1/source/Cargo.toml [INFO] validating manifest of crates.io crate ramu_rs 0.1.1 on toolchain caccb4d0368bd918ef6668af8e13834d07040417 [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+caccb4d0368bd918ef6668af8e13834d07040417" "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" "+caccb4d0368bd918ef6668af8e13834d07040417" "generate-lockfile" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] [stderr] Blocking waiting for file lock on package cache [INFO] [stderr] Updating crates.io index [INFO] [stderr] Locking 73 packages to latest compatible versions [INFO] [stderr] Adding enum-as-inner v0.5.1 (available: v0.6.1) [INFO] [stderr] Adding num_enum v0.5.11 (available: v0.7.4) [INFO] [stderr] Adding toml v0.5.11 (available: v0.9.7) [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+caccb4d0368bd918ef6668af8e13834d07040417" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] [stderr] Downloading crates ... [INFO] [stderr] Downloaded matchers v0.2.0 [INFO] [stderr] Downloaded scratch v1.0.9 [INFO] [stderr] Downloaded tracing-subscriber v0.3.20 [INFO] [stderr] Downloaded cxxbridge-cmd v1.0.186 [INFO] [stderr] Downloaded cxx-build v1.0.186 [INFO] [stderr] Downloaded nu-ansi-term v0.50.1 [INFO] [stderr] Downloaded clap v4.5.48 [INFO] [stderr] Downloaded clap_builder v4.5.48 [INFO] [stderr] Downloaded link-cplusplus v1.0.12 [INFO] [stderr] Downloaded toml_edit v0.19.15 [INFO] [stderr] Downloaded cxxbridge-flags v1.0.186 [INFO] [stderr] Downloaded cxxbridge-macro v1.0.186 [INFO] [stderr] Downloaded cxx v1.0.186 [INFO] [stderr] Downloaded winnow v0.5.40 [INFO] [stderr] Downloaded anstyle v1.0.13 [INFO] [stderr] Downloaded proc-macro-crate v1.3.1 [INFO] [stderr] Downloaded num_enum_derive v0.5.11 [INFO] [stderr] Downloaded toml v0.5.11 [INFO] [stderr] Downloaded foldhash v0.2.0 [INFO] [stderr] Downloaded enum-as-inner v0.5.1 [INFO] [stderr] Downloaded num_enum v0.5.11 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+caccb4d0368bd918ef6668af8e13834d07040417" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }` [INFO] [stdout] 8becb40a2686a3863ddc71ebc4a9ab94ab9d46b0cccffa64c7996c39164baddf [INFO] running `Command { std: "docker" "start" "-a" "8becb40a2686a3863ddc71ebc4a9ab94ab9d46b0cccffa64c7996c39164baddf", kill_on_drop: false }` [INFO] running `Command { std: "docker" "inspect" "8becb40a2686a3863ddc71ebc4a9ab94ab9d46b0cccffa64c7996c39164baddf", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "8becb40a2686a3863ddc71ebc4a9ab94ab9d46b0cccffa64c7996c39164baddf", kill_on_drop: false }` [INFO] [stdout] 8becb40a2686a3863ddc71ebc4a9ab94ab9d46b0cccffa64c7996c39164baddf [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+caccb4d0368bd918ef6668af8e13834d07040417" "build" "--frozen" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] ac739ff8c87792f8f90f9a2ac5ea883ce9fca26df388d29f430973c8efd88071 [INFO] running `Command { std: "docker" "start" "-a" "ac739ff8c87792f8f90f9a2ac5ea883ce9fca26df388d29f430973c8efd88071", kill_on_drop: false }` [INFO] [stderr] Compiling proc-macro2 v1.0.101 [INFO] [stderr] Compiling shlex v1.3.0 [INFO] [stderr] Compiling equivalent v1.0.2 [INFO] [stderr] Compiling hashbrown v0.16.0 [INFO] [stderr] Compiling find-msvc-tools v0.1.2 [INFO] [stderr] Compiling once_cell v1.21.3 [INFO] [stderr] Compiling syn v1.0.109 [INFO] [stderr] Compiling toml_datetime v0.6.11 [INFO] [stderr] Compiling winnow v0.5.40 [INFO] [stderr] Compiling rustversion v1.0.22 [INFO] [stderr] Compiling cxxbridge-flags v1.0.186 [INFO] [stderr] Compiling regex-syntax v0.8.6 [INFO] [stderr] Compiling lazy_static v1.5.0 [INFO] [stderr] Compiling pin-project-lite v0.2.16 [INFO] [stderr] Compiling cfg-if v1.0.3 [INFO] [stderr] Compiling log v0.4.28 [INFO] [stderr] Compiling nu-ansi-term v0.50.1 [INFO] [stderr] Compiling heck v0.4.1 [INFO] [stderr] Compiling sharded-slab v0.1.7 [INFO] [stderr] Compiling foldhash v0.2.0 [INFO] [stderr] Compiling thread_local v1.1.9 [INFO] [stderr] Compiling smallvec v1.15.1 [INFO] [stderr] Compiling cc v1.2.39 [INFO] [stderr] Compiling tracing-core v0.1.34 [INFO] [stderr] Compiling tracing-log v0.2.0 [INFO] [stderr] Compiling indexmap v2.11.4 [INFO] [stderr] Compiling quote v1.0.41 [INFO] [stderr] Compiling link-cplusplus v1.0.12 [INFO] [stderr] Compiling cxx v1.0.186 [INFO] [stderr] Compiling syn v2.0.106 [INFO] [stderr] Compiling regex-automata v0.4.11 [INFO] [stderr] Compiling toml_edit v0.19.15 [INFO] [stderr] Compiling enum-as-inner v0.5.1 [INFO] [stderr] Compiling proc-macro-crate v1.3.1 [INFO] [stderr] Compiling matchers v0.2.0 [INFO] [stderr] Compiling num_enum_derive v0.5.11 [INFO] [stderr] Compiling num_enum v0.5.11 [INFO] [stderr] Compiling tracing-attributes v0.1.30 [INFO] [stderr] Compiling serde_derive v1.0.228 [INFO] [stderr] Compiling cxxbridge-macro v1.0.186 [INFO] [stderr] Compiling tracing v0.1.41 [INFO] [stderr] Compiling tracing-subscriber v0.3.20 [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 29.18s [INFO] running `Command { std: "docker" "inspect" "ac739ff8c87792f8f90f9a2ac5ea883ce9fca26df388d29f430973c8efd88071", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "ac739ff8c87792f8f90f9a2ac5ea883ce9fca26df388d29f430973c8efd88071", kill_on_drop: false }` [INFO] [stdout] ac739ff8c87792f8f90f9a2ac5ea883ce9fca26df388d29f430973c8efd88071 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+caccb4d0368bd918ef6668af8e13834d07040417" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 98e81e38dae79fa303964a1314e715717d364cc1386743760fdcf4643381812f [INFO] running `Command { std: "docker" "start" "-a" "98e81e38dae79fa303964a1314e715717d364cc1386743760fdcf4643381812f", 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.01s [INFO] running `Command { std: "docker" "inspect" "98e81e38dae79fa303964a1314e715717d364cc1386743760fdcf4643381812f", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "98e81e38dae79fa303964a1314e715717d364cc1386743760fdcf4643381812f", kill_on_drop: false }` [INFO] [stdout] 98e81e38dae79fa303964a1314e715717d364cc1386743760fdcf4643381812f [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+caccb4d0368bd918ef6668af8e13834d07040417" "test" "--frozen", kill_on_drop: false }` [INFO] [stdout] 909dc630e42afb1f93010268fba9334fab6f475525d4696daa348a97edcbf797 [INFO] running `Command { std: "docker" "start" "-a" "909dc630e42afb1f93010268fba9334fab6f475525d4696daa348a97edcbf797", kill_on_drop: false }` [INFO] [stderr] Finished `test` profile [unoptimized + debuginfo] target(s) in 0.10s [INFO] [stderr] Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/ramu_rs-68ae99c1bb8f162d) [INFO] [stdout] [INFO] [stdout] running 8 tests [INFO] [stdout] 2025-10-01T17:40:12.536685Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-10-01T17:40:12.536786Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-10-01T17:40:12.536851Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-10-01T17:40:12.536902Z  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] 2025-10-01T17:40:12.536996Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.537051Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.537087Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.537119Z  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] 2025-10-01T17:40:12.537166Z  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] 2025-10-01T17:40:12.537203Z  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] 2025-10-01T17:40:12.537237Z  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] 2025-10-01T17:40:12.537272Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.537302Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.537345Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.537380Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.537411Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.537474Z  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] 2025-10-01T17:40:12.537516Z  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] 2025-10-01T17:40:12.537553Z  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] 2025-10-01T17:40:12.537590Z  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] 2025-10-01T17:40:12.537633Z  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] 2025-10-01T17:40:12.537687Z  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] 2025-10-01T17:40:12.537732Z  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] 2025-10-01T17:40:12.537772Z  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] 2025-10-01T17:40:12.537805Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.537834Z  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] 2025-10-01T17:40:12.537886Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.537917Z  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] 2025-10-01T17:40:12.537951Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.538007Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538138Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538161Z  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] 2025-10-01T17:40:12.538174Z  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] 2025-10-01T17:40:12.538203Z  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] 2025-10-01T17:40:12.538216Z  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] 2025-10-01T17:40:12.538229Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538239Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538250Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538260Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538271Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538283Z  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] 2025-10-01T17:40:12.538297Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.538309Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538319Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.538331Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.538342Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.538355Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.538366Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538376Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538386Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538396Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538406Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538416Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538427Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538437Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538466Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538477Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538488Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538499Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538509Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538520Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538530Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538540Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538550Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538560Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538570Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538580Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538592Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538602Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538612Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538622Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538632Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538642Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538653Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538663Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538673Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.538689Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-10-01T17:40:12.538792Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=1 [INFO] [stdout] 2025-10-01T17:40:12.538826Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 0] [INFO] [stdout] 2025-10-01T17:40:12.538845Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 0 [INFO] [stdout] 2025-10-01T17:40:12.538858Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=65 [INFO] [stdout] 2025-10-01T17:40:12.538872Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 1] [INFO] [stdout] 2025-10-01T17:40:12.538885Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 64 [INFO] [stdout] 2025-10-01T17:40:12.538898Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=257 [INFO] [stdout] 2025-10-01T17:40:12.538912Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 4] [INFO] [stdout] 2025-10-01T17:40:12.538927Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 256 [INFO] [stdout] test config::tests::dum_config ... ignored [INFO] [stdout] test ddr4::tests::test_address ... ok [INFO] [stdout] 2025-10-01T17:40:12.540037Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-10-01T17:40:12.540099Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-10-01T17:40:12.540184Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-10-01T17:40:12.540319Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-10-01T17:40:12.540380Z  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] 2025-10-01T17:40:12.540968Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.540995Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541006Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541015Z  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] 2025-10-01T17:40:12.541026Z  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] 2025-10-01T17:40:12.541036Z  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] 2025-10-01T17:40:12.541046Z  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] 2025-10-01T17:40:12.541055Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541064Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541073Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541082Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541091Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541100Z  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] 2025-10-01T17:40:12.541111Z  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] 2025-10-01T17:40:12.541121Z  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] 2025-10-01T17:40:12.541132Z  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] 2025-10-01T17:40:12.541149Z  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] 2025-10-01T17:40:12.541161Z  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] 2025-10-01T17:40:12.541174Z  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] 2025-10-01T17:40:12.541186Z  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] 2025-10-01T17:40:12.541196Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.541206Z  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] 2025-10-01T17:40:12.541219Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.541236Z  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] 2025-10-01T17:40:12.541246Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.541256Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541265Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541274Z  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] 2025-10-01T17:40:12.541284Z  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] 2025-10-01T17:40:12.541295Z  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] 2025-10-01T17:40:12.541305Z  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] 2025-10-01T17:40:12.541315Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541324Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541333Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541342Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541352Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541362Z  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] 2025-10-01T17:40:12.541373Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.541382Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541391Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.541401Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.541410Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.541420Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.541429Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541450Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541462Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541472Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541482Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541491Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541500Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541510Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541519Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541529Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541538Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541549Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541559Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541568Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541578Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541587Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] test scheduler::tests::test ... 2025-10-01T17:40:12.541596Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] ok [INFO] [stdout] 2025-10-01T17:40:12.541608Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541618Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541627Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541636Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541646Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541655Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541665Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541675Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541684Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541694Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541703Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541713Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541723Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-10-01T17:40:12.541769Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-10-01T17:40:12.541789Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-10-01T17:40:12.541806Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-10-01T17:40:12.541815Z  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] 2025-10-01T17:40:12.541831Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2025-10-01T17:40:12.541850Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.541853Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541860Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.541869Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541875Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2025-10-01T17:40:12.541881Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541887Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.541892Z  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] 2025-10-01T17:40:12.541898Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.541905Z  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] 2025-10-01T17:40:12.541908Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.541918Z  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] 2025-10-01T17:40:12.541920Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.541934Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.541931Z  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] 2025-10-01T17:40:12.541945Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541946Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-10-01T17:40:12.541959Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2025-10-01T17:40:12.541957Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541973Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2025-10-01T17:40:12.541979Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.541987Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2025-10-01T17:40:12.541990Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542000Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-10-01T17:40:12.542002Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542014Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2025-10-01T17:40:12.542016Z  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] 2025-10-01T17:40:12.542026Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2025-10-01T17:40:12.542031Z  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] 2025-10-01T17:40:12.542038Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2025-10-01T17:40:12.542044Z  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] 2025-10-01T17:40:12.542051Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2025-10-01T17:40:12.542057Z  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] 2025-10-01T17:40:12.542093Z  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] 2025-10-01T17:40:12.542124Z  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] 2025-10-01T17:40:12.542141Z  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] 2025-10-01T17:40:12.542171Z  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] 2025-10-01T17:40:12.542186Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.542198Z  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] 2025-10-01T17:40:12.542225Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.542238Z  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] 2025-10-01T17:40:12.542261Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.542274Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542284Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542305Z  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] 2025-10-01T17:40:12.542330Z  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] 2025-10-01T17:40:12.542344Z  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] 2025-10-01T17:40:12.542357Z  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] 2025-10-01T17:40:12.542370Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.540244Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-10-01T17:40:12.542390Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542403Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542406Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-10-01T17:40:12.542423Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.539774Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-10-01T17:40:12.542458Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542063Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2025-10-01T17:40:12.542498Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-10-01T17:40:12.542522Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-10-01T17:40:12.542516Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2025-10-01T17:40:12.542533Z  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] 2025-10-01T17:40:12.542425Z  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] 2025-10-01T17:40:12.542551Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.542567Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542573Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.542581Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542584Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542585Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.542598Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542602Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542606Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.542609Z  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] 2025-10-01T17:40:12.542615Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.542621Z  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] 2025-10-01T17:40:12.542625Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.542612Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542637Z  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] 2025-10-01T17:40:12.542640Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.542642Z  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] 2025-10-01T17:40:12.542651Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.542648Z  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] 2025-10-01T17:40:12.542653Z  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] 2025-10-01T17:40:12.542660Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.542662Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542663Z  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] 2025-10-01T17:40:12.542670Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.542672Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542673Z  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] 2025-10-01T17:40:12.542679Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.542684Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542683Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542689Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.542694Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542700Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.542695Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542707Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542709Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.542710Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542717Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542719Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.542722Z  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] 2025-10-01T17:40:12.542726Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542729Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.542736Z  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] 2025-10-01T17:40:12.542737Z  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] 2025-10-01T17:40:12.542748Z  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] 2025-10-01T17:40:12.542739Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.542755Z  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] 2025-10-01T17:40:12.542764Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.542771Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.542761Z  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] 2025-10-01T17:40:12.542787Z  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] 2025-10-01T17:40:12.542775Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.542796Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542804Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.542801Z  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] 2025-10-01T17:40:12.542812Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.542809Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.542821Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.542817Z  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] 2025-10-01T17:40:12.542823Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.542828Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.542837Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.542833Z  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] 2025-10-01T17:40:12.542835Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.542845Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.542847Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.542848Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.542853Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.542861Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.542860Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542858Z  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] 2025-10-01T17:40:12.542870Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.542871Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542873Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.542878Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.542882Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542887Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.542886Z  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] 2025-10-01T17:40:12.542896Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.542893Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542899Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.542903Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.542904Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542911Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.542909Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542915Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542919Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.542921Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542928Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.542927Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542932Z  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] 2025-10-01T17:40:12.542936Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.542938Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542945Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.542944Z  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] 2025-10-01T17:40:12.542953Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.542949Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542961Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.542971Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.542959Z  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] 2025-10-01T17:40:12.542970Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542979Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.542983Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542982Z  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] 2025-10-01T17:40:12.542988Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.542993Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.542997Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.542995Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543005Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.543004Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543007Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543013Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.543016Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543018Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543022Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.543027Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543031Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.543030Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543041Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.543040Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543043Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543050Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.543051Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543057Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.543054Z  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] 2025-10-01T17:40:12.543062Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543065Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.543069Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.543074Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.543073Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543083Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.543081Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543084Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543091Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.543093Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.543095Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543100Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.543104Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.543106Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543109Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.543115Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.543118Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.543117Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543127Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.543126Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.543129Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543135Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.543136Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543140Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543143Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.543146Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543152Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.543150Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543157Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543159Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.543161Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543168Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.543167Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543172Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543177Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.543178Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543182Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543185Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.543188Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543193Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-10-01T17:40:12.543194Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.543199Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543203Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.543210Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543211Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.543221Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543225Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.543234Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.543233Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543241Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.543243Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543249Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.543254Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543258Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.543266Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.543265Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543274Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.543275Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543282Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.543286Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543289Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.543301Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.543300Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543310Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.543312Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543311Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2025-10-01T17:40:12.543318Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.543323Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543327Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.543330Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.543335Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.543333Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543341Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.543343Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.543344Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543353Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.543353Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2025-10-01T17:40:12.543354Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543361Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.543365Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.543365Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543377Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.542788Z  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] 2025-10-01T17:40:12.543385Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543388Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.543390Z  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] 2025-10-01T17:40:12.543397Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543399Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.543401Z  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] 2025-10-01T17:40:12.543408Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543411Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.543416Z  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] 2025-10-01T17:40:12.543419Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543423Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-10-01T17:40:12.543431Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543429Z  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] 2025-10-01T17:40:12.543437Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2025-10-01T17:40:12.543461Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543465Z  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] 2025-10-01T17:40:12.543472Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543469Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2025-10-01T17:40:12.543478Z  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] 2025-10-01T17:40:12.543483Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-10-01T17:40:12.543484Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2025-10-01T17:40:12.543489Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.543499Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-10-01T17:40:12.543499Z  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] 2025-10-01T17:40:12.543515Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.543513Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2025-10-01T17:40:12.543525Z  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] 2025-10-01T17:40:12.543527Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2025-10-01T17:40:12.543536Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.543542Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2025-10-01T17:40:12.543546Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543556Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543555Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2025-10-01T17:40:12.543565Z  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] 2025-10-01T17:40:12.543568Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2025-10-01T17:40:12.543576Z  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] 2025-10-01T17:40:12.543581Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2025-10-01T17:40:12.543588Z  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] 2025-10-01T17:40:12.543594Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.543599Z  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] 2025-10-01T17:40:12.543611Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.543601Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.543625Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=0 [INFO] [stdout] 2025-10-01T17:40:12.543369Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.543637Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.543623Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543647Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.543648Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.543652Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543660Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.543662Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543661Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.543670Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.543672Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543674Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.543679Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.543681Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543685Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.543689Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.543691Z  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] 2025-10-01T17:40:12.543696Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=0 [INFO] [stdout] 2025-10-01T17:40:12.543703Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.543704Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.543712Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.543711Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=39 [INFO] [stdout] 2025-10-01T17:40:12.543715Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.543721Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.543726Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.543725Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=55 [INFO] [stdout] 2025-10-01T17:40:12.543732Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.543736Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.543740Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.543739Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=1 [INFO] [stdout] 2025-10-01T17:40:12.543746Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.543750Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.543757Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-10-01T17:40:12.543754Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=0 [INFO] [stdout] 2025-10-01T17:40:12.543761Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.543859Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.543874Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.543886Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.543895Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.543927Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.543940Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.543949Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.543972Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.543985Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544001Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.544011Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.544028Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544037Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.544053Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.544063Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544072Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.544092Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.544104Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544119Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.544130Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.544141Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544157Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.544167Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.544178Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544196Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.544206Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.544216Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544233Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.544243Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.544255Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544270Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.544280Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.544290Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544297Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.544316Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.544327Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544335Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.544352Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.544363Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544371Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.544388Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.544398Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544406Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.544416Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.544435Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544460Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.544470Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.544480Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544488Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.544497Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.544506Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544515Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.544535Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.544545Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544562Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.544572Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.544582Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544597Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.544607Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.544618Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544627Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.544644Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.544655Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544663Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.544678Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.544689Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544702Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.544711Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.544722Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544738Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.544749Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.544767Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544776Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.544785Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.544802Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544810Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.544819Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.544830Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.544846Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.544856Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.544867Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17 [INFO] [stdout] 2025-10-01T17:40:12.544882Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.544894Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.544910Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.544921Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.544933Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2025-10-01T17:40:12.544953Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2025-10-01T17:40:12.544974Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2025-10-01T17:40:12.544993Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2025-10-01T17:40:12.545007Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27 [INFO] [stdout] 2025-10-01T17:40:12.545026Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27 [INFO] [stdout] 2025-10-01T17:40:12.545040Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26 [INFO] [stdout] 2025-10-01T17:40:12.545059Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38 [INFO] [stdout] 2025-10-01T17:40:12.545081Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23 [INFO] [stdout] 2025-10-01T17:40:12.545094Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23 [INFO] [stdout] 2025-10-01T17:40:12.545113Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26 [INFO] [stdout] 2025-10-01T17:40:12.545137Z 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] 2025-10-01T17:40:12.545160Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545170Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545187Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545198Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545213Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545223Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545234Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545249Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545259Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545278Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545286Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545302Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545312Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545326Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545335Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545346Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545363Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545373Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545389Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545398Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545408Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545424Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545432Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545465Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545476Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545483Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545500Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545509Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545523Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545532Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545547Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545555Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545569Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545580Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545593Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545603Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545618Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545625Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545634Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545651Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545660Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545674Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545684Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545697Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545706Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545724Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545733Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545743Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545808Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.543783Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.545826Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545838Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545849Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545847Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.545857Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545865Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545867Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545876Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545878Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545887Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545888Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545896Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.545897Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545905Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.545909Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545916Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17 [INFO] [stdout] 2025-10-01T17:40:12.545918Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545925Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.545928Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.545937Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.545946Z 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] 2025-10-01T17:40:12.545948Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.545959Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.545972Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.545972Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2025-10-01T17:40:12.545982Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.545988Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2025-10-01T17:40:12.545993Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546005Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.546002Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2025-10-01T17:40:12.546013Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546016Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2025-10-01T17:40:12.546022Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546033Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.546029Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27 [INFO] [stdout] 2025-10-01T17:40:12.546042Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546043Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27 [INFO] [stdout] 2025-10-01T17:40:12.546052Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546057Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26 [INFO] [stdout] 2025-10-01T17:40:12.546062Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40 [INFO] [stdout] 2025-10-01T17:40:12.546069Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38 [INFO] [stdout] 2025-10-01T17:40:12.546072Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.546084Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.546083Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23 [INFO] [stdout] 2025-10-01T17:40:12.546095Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.546097Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23 [INFO] [stdout] 2025-10-01T17:40:12.546106Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-01T17:40:12.546113Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26 [INFO] [stdout] 2025-10-01T17:40:12.546120Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56 [INFO] [stdout] 2025-10-01T17:40:12.546130Z 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] 2025-10-01T17:40:12.546133Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56 [INFO] [stdout] 2025-10-01T17:40:12.546146Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546148Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56 [INFO] [stdout] 2025-10-01T17:40:12.546154Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546164Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.546163Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546172Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.546175Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546184Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.546184Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546192Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.546193Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546202Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.546204Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546235Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546250Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546261Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546270Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546295Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546316Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546325Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546345Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546357Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546366Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546386Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546397Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546418Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546429Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546465Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546476Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546486Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546507Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546516Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546535Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546545Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546553Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.543770Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=16 [INFO] [stdout] 2025-10-01T17:40:12.546572Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546583Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546578Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=16 [INFO] [stdout] 2025-10-01T17:40:12.546602Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=16 [INFO] [stdout] 2025-10-01T17:40:12.546617Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=16 [INFO] [stdout] 2025-10-01T17:40:12.546632Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=55 [INFO] [stdout] 2025-10-01T17:40:12.546646Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=39 [INFO] [stdout] 2025-10-01T17:40:12.546665Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.546675Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.546684Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.546592Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546695Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.546704Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.546703Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546713Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.546718Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546724Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.546727Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546732Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.546737Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546741Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.546748Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546751Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.546757Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546763Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.546767Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546772Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.546777Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546781Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.546785Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546789Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.546795Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546798Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.546805Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546809Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.546813Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546817Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.546821Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546827Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.546831Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546837Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.546839Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546845Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.546849Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546855Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.546859Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546864Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.546868Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546873Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.546877Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546883Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.546888Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546894Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.546896Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546903Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.546905Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546912Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.546914Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546921Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.546923Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546930Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.546932Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546939Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.546944Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546949Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.546952Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546962Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.546967Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.546978Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.546982Z 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] 2025-10-01T17:40:12.546988Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.546994Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.546997Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.547003Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.547007Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.547013Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.547017Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.547023Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547026Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.547035Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.547036Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.547044Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.547047Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.547055Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547055Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.547064Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.547065Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.547073Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.547075Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.547084Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40 [INFO] [stdout] 2025-10-01T17:40:12.547084Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.547095Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.547094Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.547105Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.547106Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.547113Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.547117Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.547123Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.547128Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-01T17:40:12.547134Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=16 [INFO] [stdout] 2025-10-01T17:40:12.547141Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56 [INFO] [stdout] 2025-10-01T17:40:12.547143Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.547156Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.547154Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56 [INFO] [stdout] 2025-10-01T17:40:12.547169Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.547174Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56 [INFO] [stdout] 2025-10-01T17:40:12.547181Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.547190Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547198Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547195Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=20 [INFO] [stdout] 2025-10-01T17:40:12.547208Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547209Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=20 [INFO] [stdout] 2025-10-01T17:40:12.547225Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547224Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=20 [INFO] [stdout] 2025-10-01T17:40:12.547237Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547238Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=20 [INFO] [stdout] 2025-10-01T17:40:12.547246Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547256Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547252Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=26 [INFO] [stdout] 2025-10-01T17:40:12.547264Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547265Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=26 [INFO] [stdout] 2025-10-01T17:40:12.547274Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547283Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547279Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=39 future=25 [INFO] [stdout] 2025-10-01T17:40:12.547293Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547296Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=1 future=37 [INFO] [stdout] 2025-10-01T17:40:12.547301Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547313Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547311Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=22 [INFO] [stdout] 2025-10-01T17:40:12.547321Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547325Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=22 [INFO] [stdout] 2025-10-01T17:40:12.547331Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547340Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547340Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=39 future=25 [INFO] [stdout] 2025-10-01T17:40:12.547351Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547359Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547356Z 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] 2025-10-01T17:40:12.547369Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547377Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547387Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547394Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547403Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547411Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547420Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547427Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547437Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547467Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547477Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547486Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547495Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.547507Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547516Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56 [INFO] [stdout] 2025-10-01T17:40:12.547523Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.547533Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.547563Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.547572Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-01T17:40:12.547588Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.546211Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547597Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2025-10-01T17:40:12.543767Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547637Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.547710Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547726Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.547754Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95 [INFO] [stdout] 2025-10-01T17:40:12.547774Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547692Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547789Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.547791Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547798Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547801Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547808Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.547817Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547820Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547828Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.547830Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547836Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547839Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547847Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.547848Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547855Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547857Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547865Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.547865Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547874Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547875Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547884Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.547885Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547893Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547894Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547903Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.547906Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547911Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547915Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547922Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.547923Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547930Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547932Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547941Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.547941Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547949Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.547950Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547965Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111 [INFO] [stdout] 2025-10-01T17:40:12.547979Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547992Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.548003Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.548013Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.548024Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.548035Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.548046Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.547978Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57 [INFO] [stdout] 2025-10-01T17:40:12.548057Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.548062Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2025-10-01T17:40:12.548067Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.548075Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72 [INFO] [stdout] 2025-10-01T17:40:12.548077Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-10-01T17:40:12.548088Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-10-01T17:40:12.548086Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72 [INFO] [stdout] 2025-10-01T17:40:12.548098Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72 [INFO] [stdout] 2025-10-01T17:40:12.548109Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72 [INFO] [stdout] 2025-10-01T17:40:12.548119Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111 [INFO] [stdout] 2025-10-01T17:40:12.548130Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95 [INFO] [stdout] 2025-10-01T17:40:12.548143Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548150Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548158Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548166Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548173Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548181Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548189Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548196Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548203Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548212Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548224Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548232Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548228Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2025-10-01T17:40:12.548240Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548249Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548248Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548256Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548259Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.548265Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548271Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548271Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2025-10-01T17:40:12.548279Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548281Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.548287Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548294Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548293Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.548302Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548305Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.548310Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548317Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548316Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.548325Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548327Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.548333Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548340Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548337Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-10-01T17:40:12.548348Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548356Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548351Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2025-10-01T17:40:12.548363Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548370Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548367Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2025-10-01T17:40:12.548378Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548386Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548382Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2025-10-01T17:40:12.548393Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548401Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548396Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-10-01T17:40:12.548408Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548416Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548411Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2025-10-01T17:40:12.548424Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548431Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548426Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2025-10-01T17:40:12.548502Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2025-10-01T17:40:12.548460Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548522Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2025-10-01T17:40:12.548539Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548538Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2025-10-01T17:40:12.548551Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2025-10-01T17:40:12.548559Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548568Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548569Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548576Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548578Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.548583Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548588Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548591Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548599Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548598Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548606Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548608Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548614Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548617Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.548622Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=72 [INFO] [stdout] 2025-10-01T17:40:12.548628Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548630Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.548637Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.548640Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.548646Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548649Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.548656Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548660Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-01T17:40:12.548665Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548670Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=76 [INFO] [stdout] 2025-10-01T17:40:12.548675Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.548681Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=76 [INFO] [stdout] 2025-10-01T17:40:12.548685Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548693Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=27 future=76 [INFO] [stdout] 2025-10-01T17:40:12.548695Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.548705Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548703Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=27 future=76 [INFO] [stdout] 2025-10-01T17:40:12.548715Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548715Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=21 future=91 [INFO] [stdout] 2025-10-01T17:40:12.548723Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548726Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=21 future=91 [INFO] [stdout] 2025-10-01T17:40:12.548733Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.548737Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=95 future=106 [INFO] [stdout] 2025-10-01T17:40:12.548744Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548748Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=57 future=106 [INFO] [stdout] 2025-10-01T17:40:12.548752Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.548759Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=78 [INFO] [stdout] 2025-10-01T17:40:12.548761Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548792Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=78 [INFO] [stdout] 2025-10-01T17:40:12.548796Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548804Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=23 future=97 [INFO] [stdout] 2025-10-01T17:40:12.548806Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548814Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=23 future=97 [INFO] [stdout] 2025-10-01T17:40:12.548816Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.548828Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548826Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=95 future=106 [INFO] [stdout] 2025-10-01T17:40:12.548836Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.548845Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548845Z 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] 2025-10-01T17:40:12.548855Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548856Z 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] 2025-10-01T17:40:12.548864Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548874Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.548884Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548892Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.548901Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548912Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548920Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548929Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.548939Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548950Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.548970Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.548981Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.548989Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.548999Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.549010Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549018Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.549027Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.549037Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549054Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.549065Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] test test::test_memory_read_and_write ... ok2025-10-01T17:40:12.549075Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] [INFO] [stdout] 2025-10-01T17:40:12.549085Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.549094Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.549105Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549113Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.549123Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.549137Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549146Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.549156Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.549166Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549174Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.549183Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.549197Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549206Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.549216Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.549226Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549234Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.549253Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.549264Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549273Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.549286Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.549296Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549305Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.549321Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.549331Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549340Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.549350Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.549360Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549371Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.549381Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.549391Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549400Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.549409Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.549419Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549428Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.549437Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.549470Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549487Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.549497Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.549511Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549520Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.549530Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.549541Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549549Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-10-01T17:40:12.549558Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.549570Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=17 [INFO] [stdout] 2025-10-01T17:40:12.549580Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.549591Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.549602Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.549613Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.549626Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=21 [INFO] [stdout] 2025-10-01T17:40:12.549640Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=21 [INFO] [stdout] 2025-10-01T17:40:12.549654Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=0 future=21 [INFO] [stdout] 2025-10-01T17:40:12.549667Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=0 future=21 [INFO] [stdout] 2025-10-01T17:40:12.549681Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=0 future=36 [INFO] [stdout] 2025-10-01T17:40:12.549694Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=0 future=36 [INFO] [stdout] 2025-10-01T17:40:12.549707Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=40 future=51 [INFO] [stdout] 2025-10-01T17:40:12.549720Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=2 future=51 [INFO] [stdout] 2025-10-01T17:40:12.549735Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=23 [INFO] [stdout] 2025-10-01T17:40:12.549748Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=23 [INFO] [stdout] 2025-10-01T17:40:12.549763Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=0 future=42 [INFO] [stdout] 2025-10-01T17:40:12.549777Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=0 future=42 [INFO] [stdout] 2025-10-01T17:40:12.549791Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=40 future=51 [INFO] [stdout] 2025-10-01T17:40:12.549806Z 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] 2025-10-01T17:40:12.549827Z 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] 2025-10-01T17:40:12.549838Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549847Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.549857Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.549868Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549877Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.549886Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.549897Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549905Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.549915Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.549925Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549934Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.549943Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.549954Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.549976Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.549986Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.549997Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.550005Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.550015Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.550026Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.550037Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.550046Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.550056Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.550065Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.550075Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.550086Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.550094Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.550103Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.550114Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.550123Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.550132Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.550143Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.550151Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.550160Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.550171Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.550180Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.550189Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.550199Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.550207Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.550217Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.550228Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.550236Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.550245Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.550255Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.550264Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.550274Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.550284Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.550292Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.550304Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.550315Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.550324Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.550333Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.550344Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.550352Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.550361Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.550372Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.550380Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.550390Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.550400Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.550408Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.550418Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.550429Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.555460Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.555508Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.555526Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.555549Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.555561Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.555578Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.555588Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.555601Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.555612Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.555621Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.555631Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.555641Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.555650Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.555669Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.555681Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.555696Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.555706Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.555724Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.555733Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.555741Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.555752Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.555760Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.555776Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.555788Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.555796Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.555811Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.555823Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.555837Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.555847Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.555866Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.555875Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.555884Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.555901Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stderr] error: test failed, to rerun pass `--lib` [INFO] [stdout] 2025-10-01T17:40:12.555911Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.555926Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.555937Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.555946Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.555975Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.555987Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.555997Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.556007Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-10-01T17:40:12.556027Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=51 [INFO] [stdout] 2025-10-01T17:40:12.556038Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.556058Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.556070Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.556088Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-01T17:40:12.556103Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=67 [INFO] [stdout] 2025-10-01T17:40:12.556124Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=67 [INFO] [stdout] 2025-10-01T17:40:12.556140Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=67 [INFO] [stdout] 2025-10-01T17:40:12.556163Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.556173Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.556188Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.556197Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.556208Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.556217Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.556228Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.556245Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.556257Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.556271Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.556282Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.556296Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.556307Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.556316Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.556326Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.556334Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.556344Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.556353Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.556364Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.556372Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.556382Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.556390Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.556401Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.556409Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.556428Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.556465Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.556479Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.556492Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.556501Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.556512Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56 [INFO] [stdout] 2025-10-01T17:40:12.556522Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.556534Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.556555Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.556566Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-01T17:40:12.556580Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.556592Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2025-10-01T17:40:12.556608Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95 [INFO] [stdout] 2025-10-01T17:40:12.556622Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111 [INFO] [stdout] 2025-10-01T17:40:12.556635Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57 [INFO] [stdout] 2025-10-01T17:40:12.556650Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2025-10-01T17:40:12.556664Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72 [INFO] [stdout] 2025-10-01T17:40:12.556678Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72 [INFO] [stdout] 2025-10-01T17:40:12.556691Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72 [INFO] [stdout] 2025-10-01T17:40:12.556710Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72 [INFO] [stdout] 2025-10-01T17:40:12.556724Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111 [INFO] [stdout] 2025-10-01T17:40:12.556736Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95 [INFO] [stdout] 2025-10-01T17:40:12.556763Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.556773Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.556790Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.556801Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.556809Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.556824Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.556835Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.556844Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.556853Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.556873Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.556882Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.556899Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.556910Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.556927Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.556937Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.556954Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.556971Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.556988Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.556998Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.557014Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.557022Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.557039Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.557047Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.557055Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.557066Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.557080Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.557089Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.557098Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.557106Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.557115Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.557124Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.557132Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.557146Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.557155Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.557162Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.557171Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.557180Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.557188Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.557196Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.557206Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.557224Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.557234Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.557243Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.557260Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.557269Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.557278Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-10-01T17:40:12.557291Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.557300Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-10-01T17:40:12.557317Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=72 [INFO] [stdout] 2025-10-01T17:40:12.557326Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.557344Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.557354Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.557365Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-01T17:40:12.557383Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=21 future=76 [INFO] [stdout] 2025-10-01T17:40:12.557396Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=21 future=76 [INFO] [stdout] 2025-10-01T17:40:12.557409Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=21 future=76 [INFO] [stdout] 2025-10-01T17:40:12.557420Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=21 future=76 [INFO] [stdout] 2025-10-01T17:40:12.557433Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=27 future=82 [INFO] [stdout] 2025-10-01T17:40:12.559495Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=27 future=82 [INFO] [stdout] 2025-10-01T17:40:12.559515Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=95 future=81 [INFO] [stdout] 2025-10-01T17:40:12.559533Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=57 future=93 [INFO] [stdout] 2025-10-01T17:40:12.559548Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=23 future=78 [INFO] [stdout] 2025-10-01T17:40:12.559561Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=23 future=78 [INFO] [stdout] 2025-10-01T17:40:12.559575Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=95 future=81 [INFO] [stdout] 2025-10-01T17:40:12.559593Z 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] 2025-10-01T17:40:12.559615Z 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] 2025-10-01T17:40:12.556437Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.560009Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.560024Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.560035Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.560075Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.560120Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.560171Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-10-01T17:40:12.560216Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=67 [INFO] [stdout] 2025-10-01T17:40:12.560252Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.560292Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.560332Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.560375Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-01T17:40:12.560415Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.560470Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=67 [INFO] [stdout] 2025-10-01T17:40:12.560522Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=51 future=106 [INFO] [stdout] 2025-10-01T17:40:12.560560Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=67 future=122 [INFO] [stdout] 2025-10-01T17:40:12.560604Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=51 future=68 [INFO] [stdout] 2025-10-01T17:40:12.560655Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=67 [INFO] [stdout] 2025-10-01T17:40:12.560705Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=83 [INFO] [stdout] 2025-10-01T17:40:12.560744Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=83 [INFO] [stdout] 2025-10-01T17:40:12.560792Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=83 [INFO] [stdout] 2025-10-01T17:40:12.560836Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=83 [INFO] [stdout] 2025-10-01T17:40:12.560870Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=67 future=122 [INFO] [stdout] 2025-10-01T17:40:12.560923Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=51 future=106 [INFO] [stdout] 2025-10-01T17:40:12.560975Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.561011Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.561043Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.561074Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.561107Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.561138Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.561178Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.561209Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.561249Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.561281Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.561309Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.561355Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.561385Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.561415Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.561458Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.561489Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.561514Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.561553Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.561582Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.561607Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.561633Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.561672Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.561702Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.561739Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.561773Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.561810Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.567484Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.567571Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.567605Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.567637Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.567681Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.567712Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.567741Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.567772Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.567800Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.567827Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.567854Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.567878Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.567904Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.567932Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.567982Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.568015Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.568043Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.568069Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.568097Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.568127Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-10-01T17:40:12.568155Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-10-01T17:40:12.568201Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-10-01T17:40:12.568235Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=83 [INFO] [stdout] 2025-10-01T17:40:12.568266Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.568310Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.568343Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-10-01T17:40:12.568371Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-10-01T17:40:12.568410Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=21 future=87 [INFO] [stdout] 2025-10-01T17:40:12.568497Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=21 future=87 [INFO] [stdout] 2025-10-01T17:40:12.568554Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=21 future=87 [INFO] [stdout] 2025-10-01T17:40:12.568591Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=21 future=87 [INFO] [stdout] 2025-10-01T17:40:12.568627Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=36 future=102 [INFO] [stdout] 2025-10-01T17:40:12.568677Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=36 future=102 [INFO] [stdout] 2025-10-01T17:40:12.568713Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=106 future=117 [INFO] [stdout] 2025-10-01T17:40:12.568749Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=68 future=117 [INFO] [stdout] 2025-10-01T17:40:12.568828Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=23 future=89 [INFO] [stdout] 2025-10-01T17:40:12.568873Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=23 future=89 [INFO] [stdout] 2025-10-01T17:40:12.568909Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=42 future=108 [INFO] [stdout] 2025-10-01T17:40:12.568944Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=42 future=108 [INFO] [stdout] 2025-10-01T17:40:12.568991Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=106 future=117 [INFO] [stdout] 2025-10-01T17:40:12.569043Z 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] 2025-10-01T17:40:12.570469Z 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] test test::test_memory_write ... ok [INFO] [stdout] test utils::tests::test_addr ... ok [INFO] [stdout] test controller::tests::test_controller_simple_read ... FAILED [INFO] [stdout] [INFO] [stdout] failures: [INFO] [stdout] [INFO] [stdout] ---- controller::tests::test_controller_simple_read stdout ---- [INFO] [stdout] Failed to init tracing: a global default trace dispatcher has already been set [INFO] [stdout] [INFO] [stdout] thread 'controller::tests::test_controller_simple_read' (25) panicked at src/controller.rs:300:9: [INFO] [stdout] assertion failed: controller.finished_queue.is_empty() [INFO] [stdout] stack backtrace: [INFO] [stdout] 0: 0x5b8ecf094f82 - std::backtrace_rs::backtrace::libunwind::trace::h76861be37b31432e [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/../../backtrace/src/backtrace/libunwind.rs:117:9 [INFO] [stdout] 1: 0x5b8ecf094f82 - std::backtrace_rs::backtrace::trace_unsynchronized::h58d4003082192c17 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/../../backtrace/src/backtrace/mod.rs:66:14 [INFO] [stdout] 2: 0x5b8ecf094f82 - std::sys::backtrace::_print_fmt::hfe5857a399620d2a [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/sys/backtrace.rs:66:9 [INFO] [stdout] 3: 0x5b8ecf094f82 - ::fmt::h52160e9da139e442 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/sys/backtrace.rs:39:26 [INFO] [stdout] 4: 0x5b8ecf0a644f - core::fmt::rt::Argument::fmt::h66fe6fef9ecca14a [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/core/src/fmt/rt.rs:173:76 [INFO] [stdout] 5: 0x5b8ecf0a644f - core::fmt::write::hf09a056a304e021a [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/core/src/fmt/mod.rs:1468:25 [INFO] [stdout] 6: 0x5b8ecf061d71 - std::io::default_write_fmt::hf1a3645468226e09 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/io/mod.rs:639:11 [INFO] [stdout] 7: 0x5b8ecf061d71 - std::io::Write::write_fmt::ha5ada6d6a18bde33 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/io/mod.rs:1954:13 [INFO] [stdout] 8: 0x5b8ecf06de42 - std::sys::backtrace::BacktraceLock::print::h15104dbcf0fd1f14 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/sys/backtrace.rs:42:9 [INFO] [stdout] 9: 0x5b8ecf072b3f - std::panicking::default_hook::{{closure}}::h0fa6cd8dbe0dd76b [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/panicking.rs:301:27 [INFO] [stdout] 10: 0x5b8ecf0729d1 - std::panicking::default_hook::h8d20506cf72e4831 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/panicking.rs:325:9 [INFO] [stdout] 11: 0x5b8ecee8492e - as core::ops::function::Fn>::call::h3d020961abd83a77 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/alloc/src/boxed.rs:1987:9 [INFO] [stdout] 12: 0x5b8ecee8492e - test::test_main_with_exit_callback::{{closure}}::h720dd2fdb2ddcdca [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/test/src/lib.rs:145:21 [INFO] [stdout] 13: 0x5b8ecf0731ff - as core::ops::function::Fn>::call::h75334a5fed245bca [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/alloc/src/boxed.rs:1987:9 [INFO] [stdout] 14: 0x5b8ecf0731ff - std::panicking::panic_with_hook::h746880a052e02c85 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/panicking.rs:842:13 [INFO] [stdout] 15: 0x5b8ecf073026 - std::panicking::panic_handler::{{closure}}::h14b95830f89d14b3 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/panicking.rs:700:13 [INFO] [stdout] 16: 0x5b8ecf06df79 - std::sys::backtrace::__rust_end_short_backtrace::h7ddaac0e9609a83d [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/sys/backtrace.rs:174:18 [INFO] [stdout] 17: 0x5b8ecf05626d - __rustc[76f7e7187978e2f8]::rust_begin_unwind [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/panicking.rs:698:5 [INFO] [stdout] 18: 0x5b8ecf0afbd0 - core::panicking::panic_fmt::heb245a301f4395db [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/core/src/panicking.rs:78:14 [INFO] [stdout] 19: 0x5b8ecf0afbac - core::panicking::panic::h43cc40e5e3a930ed [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/core/src/panicking.rs:148:5 [INFO] [stdout] 20: 0x5b8ecee4777f - ramu_rs::controller::tests::test_controller_simple_read::hdbad917d98b3a538 [INFO] [stdout] at /opt/rustwide/workdir/src/controller.rs:300:9 [INFO] [stdout] 21: 0x5b8ecee47887 - ramu_rs::controller::tests::test_controller_simple_read::{{closure}}::ha1ac7db8c06b7ea7 [INFO] [stdout] at /opt/rustwide/workdir/src/controller.rs:277:37 [INFO] [stdout] 22: 0x5b8ecee57176 - core::ops::function::FnOnce::call_once::ha933fc57e71585d9 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/core/src/ops/function.rs:250:5 [INFO] [stdout] 23: 0x5b8ecee8475b - core::ops::function::FnOnce::call_once::h933a5d67211adff2 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/core/src/ops/function.rs:250:5 [INFO] [stdout] 24: 0x5b8ecee8475b - test::__rust_begin_short_backtrace::h2157af19b0990ffb [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/test/src/lib.rs:663:18 [INFO] [stdout] 25: 0x5b8ecee9a335 - test::run_test_in_process::{{closure}}::hc3b17e0f313c900a [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/test/src/lib.rs:686:74 [INFO] [stdout] 26: 0x5b8ecee9a335 - as core::ops::function::FnOnce<()>>::call_once::ha23e4b490259273c [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/core/src/panic/unwind_safe.rs:274:9 [INFO] [stdout] 27: 0x5b8ecee9a335 - std::panicking::catch_unwind::do_call::h8dc9d5da83792f7a [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/panicking.rs:590:40 [INFO] [stdout] 28: 0x5b8ecee9a335 - std::panicking::catch_unwind::h0d8461330de4a18b [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/panicking.rs:553:19 [INFO] [stdout] 29: 0x5b8ecee9a335 - std::panic::catch_unwind::h0321b51397bf9811 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/panic.rs:359:14 [INFO] [stdout] 30: 0x5b8ecee9a335 - test::run_test_in_process::hcaaa440fdbe4a513 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/test/src/lib.rs:686:27 [INFO] [stdout] 31: 0x5b8ecee9a335 - test::run_test::{{closure}}::h6345da602b85d6c3 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/test/src/lib.rs:607:43 [INFO] [stdout] 32: 0x5b8ecee70b44 - test::run_test::{{closure}}::h90a3b75194d37b5d [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/test/src/lib.rs:637:41 [INFO] [stdout] 33: 0x5b8ecee70b44 - std::sys::backtrace::__rust_begin_short_backtrace::hae41a17001f53ede [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/sys/backtrace.rs:158:18 [INFO] [stdout] 34: 0x5b8ecee7440a - std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}::h6ea895368381e0b1 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/thread/mod.rs:559:17 [INFO] [stdout] 35: 0x5b8ecee7440a - as core::ops::function::FnOnce<()>>::call_once::h9c39013633bb9237 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/core/src/panic/unwind_safe.rs:274:9 [INFO] [stdout] 36: 0x5b8ecee7440a - std::panicking::catch_unwind::do_call::hac7dba9ee4d99108 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/panicking.rs:590:40 [INFO] [stdout] 37: 0x5b8ecee7440a - std::panicking::catch_unwind::h73015d00e4866ebc [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/panicking.rs:553:19 [INFO] [stdout] 38: 0x5b8ecee7440a - std::panic::catch_unwind::h6f7b38e188aa4f62 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/panic.rs:359:14 [INFO] [stdout] 39: 0x5b8ecee7440a - std::thread::Builder::spawn_unchecked_::{{closure}}::h969a6a2dc1856df7 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/thread/mod.rs:557:30 [INFO] [stdout] 40: 0x5b8ecee7440a - core::ops::function::FnOnce::call_once{{vtable.shim}}::h269ad1ff23e72122 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/core/src/ops/function.rs:250:5 [INFO] [stdout] 41: 0x5b8ecf0690bf - as core::ops::function::FnOnce>::call_once::hdd09a470c130e806 [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/alloc/src/boxed.rs:1973:9 [INFO] [stdout] 42: 0x5b8ecf0690bf - std::sys::thread::unix::Thread::new::thread_start::h14ea1ba6e320367c [INFO] [stdout] at /rustc/caccb4d0368bd918ef6668af8e13834d07040417/library/std/src/sys/thread/unix.rs:126:17 [INFO] [stdout] 43: 0x7702234b5aa4 - [INFO] [stdout] 44: 0x770223542a34 - clone [INFO] [stdout] 45: 0x0 - [INFO] [stdout] [INFO] [stdout] [INFO] [stdout] failures: [INFO] [stdout] controller::tests::test_controller_simple_read [INFO] [stdout] [INFO] [stdout] test result: FAILED. 6 passed; 1 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.09s [INFO] [stdout] [INFO] running `Command { std: "docker" "inspect" "909dc630e42afb1f93010268fba9334fab6f475525d4696daa348a97edcbf797", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "909dc630e42afb1f93010268fba9334fab6f475525d4696daa348a97edcbf797", kill_on_drop: false }` [INFO] [stdout] 909dc630e42afb1f93010268fba9334fab6f475525d4696daa348a97edcbf797