[INFO] fetching crate ramu_rs 0.1.1...
[INFO] testing ramu_rs-0.1.1 against 1.95.0 for beta-1.96-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 1.95.0
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.95.0" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.95.0" "generate-lockfile" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Updating crates.io index
[INFO] [stderr]      Locking 62 packages to latest compatible versions
[INFO] [stderr]       Adding enum-as-inner v0.5.1 (available: v0.7.0)
[INFO] [stderr]       Adding num_enum v0.5.11 (available: v0.7.6)
[INFO] [stderr]       Adding toml v0.5.11 (available: v1.1.2+spec-1.1.0)
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1.95.0" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded cxxbridge-flags v1.0.194
[INFO] [stderr]   Downloaded enum-as-inner v0.5.1
[INFO] [stderr]   Downloaded cxx-build v1.0.194
[INFO] [stderr]   Downloaded cxxbridge-cmd v1.0.194
[INFO] [stderr]   Downloaded cxx v1.0.194
[INFO] [stderr]   Downloaded cxxbridge-macro v1.0.194
[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:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+1.95.0" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] f3b27c015f52c73d1689f57eef79be39dce2eed8f0ec1c44c001a6c65cbaa1ef
[INFO] running `Command { std: "docker" "start" "-a" "f3b27c015f52c73d1689f57eef79be39dce2eed8f0ec1c44c001a6c65cbaa1ef", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "f3b27c015f52c73d1689f57eef79be39dce2eed8f0ec1c44c001a6c65cbaa1ef", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "f3b27c015f52c73d1689f57eef79be39dce2eed8f0ec1c44c001a6c65cbaa1ef", kill_on_drop: false }`
[INFO] [stdout] f3b27c015f52c73d1689f57eef79be39dce2eed8f0ec1c44c001a6c65cbaa1ef
[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=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+1.95.0" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 94d0034a33a0091301438e5089b0f328c4584beda2bfedda122ea4a3e6841393
[INFO] running `Command { std: "docker" "start" "-a" "94d0034a33a0091301438e5089b0f328c4584beda2bfedda122ea4a3e6841393", kill_on_drop: false }`
[INFO] [stderr]    Compiling equivalent v1.0.2
[INFO] [stderr]    Compiling hashbrown v0.17.0
[INFO] [stderr]    Compiling syn v1.0.109
[INFO] [stderr]    Compiling toml_datetime v0.6.11
[INFO] [stderr]    Compiling winnow v0.5.40
[INFO] [stderr]    Compiling cxxbridge-flags v1.0.194
[INFO] [stderr]    Compiling regex-syntax v0.8.10
[INFO] [stderr]    Compiling link-cplusplus v1.0.12
[INFO] [stderr]    Compiling foldhash v0.2.0
[INFO] [stderr]    Compiling syn v2.0.117
[INFO] [stderr]    Compiling cxx v1.0.194
[INFO] [stderr]    Compiling indexmap v2.14.0
[INFO] [stderr]    Compiling regex-automata v0.4.14
[INFO] [stderr]    Compiling toml_edit v0.19.15
[INFO] [stderr]    Compiling enum-as-inner v0.5.1
[INFO] [stderr]    Compiling matchers v0.2.0
[INFO] [stderr]    Compiling proc-macro-crate v1.3.1
[INFO] [stderr]    Compiling tracing-attributes v0.1.31
[INFO] [stderr]    Compiling serde_derive v1.0.228
[INFO] [stderr]    Compiling cxxbridge-macro v1.0.194
[INFO] [stderr]    Compiling num_enum_derive v0.5.11
[INFO] [stderr]    Compiling tracing v0.1.44
[INFO] [stderr]    Compiling num_enum v0.5.11
[INFO] [stderr]    Compiling tracing-subscriber v0.3.23
[INFO] [stderr]    Compiling serde v1.0.228
[INFO] [stderr]    Compiling toml v0.5.11
[INFO] [stderr]    Compiling ramu_rs v0.1.1 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 12.10s
[INFO] running `Command { std: "docker" "inspect" "94d0034a33a0091301438e5089b0f328c4584beda2bfedda122ea4a3e6841393", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "94d0034a33a0091301438e5089b0f328c4584beda2bfedda122ea4a3e6841393", kill_on_drop: false }`
[INFO] [stdout] 94d0034a33a0091301438e5089b0f328c4584beda2bfedda122ea4a3e6841393
[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=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+1.95.0" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] c2705ed522ce0793484ba87d9a62a112d8f819782fa4e48e938526a3046e8634
[INFO] running `Command { std: "docker" "start" "-a" "c2705ed522ce0793484ba87d9a62a112d8f819782fa4e48e938526a3046e8634", 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.13s
[INFO] running `Command { std: "docker" "inspect" "c2705ed522ce0793484ba87d9a62a112d8f819782fa4e48e938526a3046e8634", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "c2705ed522ce0793484ba87d9a62a112d8f819782fa4e48e938526a3046e8634", kill_on_drop: false }`
[INFO] [stdout] c2705ed522ce0793484ba87d9a62a112d8f819782fa4e48e938526a3046e8634
[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=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+1.95.0" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 75942097cc80c3f907368161fa358e63b4642003dd5db7287555617796989096
[INFO] running `Command { std: "docker" "start" "-a" "75942097cc80c3f907368161fa358e63b4642003dd5db7287555617796989096", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.09s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/ramu_rs-ce4d82e5a3049ae4)
[INFO] [stdout] 
[INFO] [stdout] running 8 tests
[INFO] [stdout] test config::tests::dum_config ... ignored
[INFO] [stdout] 2026-04-24T21:32:10.521288Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2026-04-24T21:32:10.521426Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2026-04-24T21:32:10.521461Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2026-04-24T21:32:10.521485Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 }
[INFO] [stdout] 2026-04-24T21:32:10.521597Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.521630Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.521644Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.521666Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.521692Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.521716Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.521732Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.521756Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.521770Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.521792Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.521805Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.521827Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.521841Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.521870Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.521915Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.521945Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.521988Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522026Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522060Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522086Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522105Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522121Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522150Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522167Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522191Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522207Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522220Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522234Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522252Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522272Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522291Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522311Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522326Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522341Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522355Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522370Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522383Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522405Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522422Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522436Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522450Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522466Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522481Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.522495Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522508Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522522Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522534Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522547Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522561Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522573Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522587Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522600Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522623Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522636Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522648Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522662Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522676Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522688Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522702Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522716Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522730Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522744Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522760Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522774Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522788Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522801Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522815Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522830Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522845Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522860Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522874Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522908Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.522931Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2026-04-24T21:32:10.523066Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192
[INFO] [stdout] 2026-04-24T21:32:10.523106Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.523122Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.523140Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1
[INFO] [stdout] 2026-04-24T21:32:10.523155Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.523170Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.523185Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.523198Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.523216Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.523231Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2026-04-24T21:32:10.523250Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40
[INFO] [stdout] 2026-04-24T21:32:10.523267Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56
[INFO] [stdout] 2026-04-24T21:32:10.523284Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2
[INFO] [stdout] 2026-04-24T21:32:10.523302Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2026-04-24T21:32:10.523319Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17
[INFO] [stdout] 2026-04-24T21:32:10.523336Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17
[INFO] [stdout] 2026-04-24T21:32:10.523354Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17
[INFO] [stdout] 2026-04-24T21:32:10.523371Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17
[INFO] [stdout] 2026-04-24T21:32:10.523389Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56
[INFO] [stdout] 2026-04-24T21:32:10.523407Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40
[INFO] [stdout] 2026-04-24T21:32:10.523429Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.523444Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.523458Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.523471Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.523482Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.523494Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.523508Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.523518Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.523531Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.523545Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.523557Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.523570Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.523583Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.523593Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.523616Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.523630Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.523641Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.523653Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.523667Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.523678Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.523690Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.523704Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.523714Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.523727Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.523740Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.523751Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.523764Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.523778Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.523789Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.523801Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.523815Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.523825Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.523838Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.523851Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.523863Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.523875Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.523921Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2026-04-24T21:32:10.523945Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2026-04-24T21:32:10.523962Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2026-04-24T21:32:10.523976Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 }
[INFO] [stdout] 2026-04-24T21:32:10.524028Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524046Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524060Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524074Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524091Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524108Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524125Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524144Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524158Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524173Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524187Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524201Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524216Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524239Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524260Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524283Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524314Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524340Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524373Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524401Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524420Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524439Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524468Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524485Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524506Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524523Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524538Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524553Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524571Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524592Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524620Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524641Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524656Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524671Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524688Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524703Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524718Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524741Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524757Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524772Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524789Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524806Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524823Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.524840Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524855Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524870Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524883Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524916Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524929Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524943Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524956Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524969Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524981Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.524995Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525008Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525022Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525036Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525050Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525064Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525078Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525092Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525106Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525120Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525134Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525149Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525163Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525177Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525191Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525205Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525219Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525233Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525246Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.525261Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2026-04-24T21:32:10.525363Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.525375Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.525389Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=0
[INFO] [stdout] 2026-04-24T21:32:10.525403Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.525417Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.525431Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.525446Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.525461Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.525472Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=0
[INFO] [stdout] 2026-04-24T21:32:10.525490Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=39
[INFO] [stdout] 2026-04-24T21:32:10.525508Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=55
[INFO] [stdout] 2026-04-24T21:32:10.525526Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=1
[INFO] [stdout] 2026-04-24T21:32:10.525544Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=0
[INFO] [stdout] 2026-04-24T21:32:10.525562Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=16
[INFO] [stdout] 2026-04-24T21:32:10.525579Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=16
[INFO] [stdout] 2026-04-24T21:32:10.525596Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=16
[INFO] [stdout] 2026-04-24T21:32:10.525623Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=16
[INFO] [stdout] 2026-04-24T21:32:10.525641Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=55
[INFO] [stdout] 2026-04-24T21:32:10.525658Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=39
[INFO] [stdout] 2026-04-24T21:32:10.525679Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.525689Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.525702Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.525715Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.525727Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.525740Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.525752Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.525762Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.525774Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.525787Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.525797Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.525810Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.525822Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.525832Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.525845Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.525857Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.525868Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.525880Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.525910Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.525921Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.525934Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.525946Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.525957Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.525969Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.525982Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.525992Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.526004Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.526017Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.526027Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.526040Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.526052Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.526062Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.526076Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.526089Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.526099Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.526112Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.526124Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.526135Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.526147Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.526160Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.526170Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.526182Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.526195Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.526205Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.526217Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.526231Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.526241Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.526253Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.526266Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=16
[INFO] [stdout] 2026-04-24T21:32:10.526278Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.526292Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.526307Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.526321Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.526336Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=20
[INFO] [stdout] 2026-04-24T21:32:10.526354Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=20
[INFO] [stdout] 2026-04-24T21:32:10.526372Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=20
[INFO] [stdout] 2026-04-24T21:32:10.526391Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=20
[INFO] [stdout] 2026-04-24T21:32:10.526409Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=26
[INFO] [stdout] 2026-04-24T21:32:10.526426Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=26
[INFO] [stdout] 2026-04-24T21:32:10.526444Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=39 future=25
[INFO] [stdout] 2026-04-24T21:32:10.526462Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=1 future=37
[INFO] [stdout] 2026-04-24T21:32:10.526479Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=22
[INFO] [stdout] 2026-04-24T21:32:10.526495Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=22
[INFO] [stdout] 2026-04-24T21:32:10.526512Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=39 future=25
[INFO] [stdout] 2026-04-24T21:32:10.526536Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 36 } clk=16 req.finish_time=36
[INFO] [stdout] 2026-04-24T21:32:10.526915Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.526936Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.526950Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.526964Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.526974Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.526985Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.526998Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.527008Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.527020Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.527032Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.527042Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.527054Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.527068Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.527078Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.527090Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.527102Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.527113Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.527124Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.527137Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.527146Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.527158Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.527170Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.527180Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.527192Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.527205Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.527214Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.527226Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.527239Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.527249Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.527260Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.527272Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.527282Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.527294Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.527306Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.527316Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.527328Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.527340Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.527350Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.527362Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.527374Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.527517Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.527534Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.527547Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.527558Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.527584Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.527597Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.527614Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.527626Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.527638Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.527648Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.527659Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.527671Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.527682Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.527694Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.527707Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.527718Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.527729Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.527742Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=17
[INFO] [stdout] 2026-04-24T21:32:10.527754Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.527768Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.527783Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.527797Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.527812Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=21
[INFO] [stdout] 2026-04-24T21:32:10.527829Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=21
[INFO] [stdout] 2026-04-24T21:32:10.527847Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=0 future=21
[INFO] [stdout] 2026-04-24T21:32:10.527867Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=0 future=21
[INFO] [stdout] 2026-04-24T21:32:10.527884Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=0 future=36
[INFO] [stdout] 2026-04-24T21:32:10.527918Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=0 future=36
[INFO] [stdout] 2026-04-24T21:32:10.527936Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=40 future=51
[INFO] [stdout] 2026-04-24T21:32:10.527951Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=2 future=51
[INFO] [stdout] 2026-04-24T21:32:10.527969Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=23
[INFO] [stdout] 2026-04-24T21:32:10.527987Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=23
[INFO] [stdout] 2026-04-24T21:32:10.528004Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=0 future=42
[INFO] [stdout] 2026-04-24T21:32:10.528021Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=0 future=42
[INFO] [stdout] 2026-04-24T21:32:10.528039Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=40 future=51
[INFO] [stdout] 2026-04-24T21:32:10.528064Z DEBUG ramu_rs::controller: write request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 17 }
[INFO] [stdout] 2026-04-24T21:32:10.528082Z DEBUG ramu_rs::test: recv req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 17 }
[INFO] [stdout] 2026-04-24T21:32:10.528096Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528107Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528118Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528132Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528142Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528154Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528167Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528177Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528191Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528203Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528214Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528226Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528238Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528248Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528260Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528272Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528282Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528293Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528306Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528316Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528327Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528340Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528350Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528363Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528375Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528386Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528398Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528410Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528420Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528432Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528445Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528456Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528468Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528481Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528492Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528504Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528519Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528529Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528541Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528553Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528563Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528576Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528612Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528622Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528634Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528647Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528657Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528669Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528681Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528692Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528704Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528716Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528726Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528738Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528750Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528760Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528771Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528784Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528794Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528807Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528820Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528830Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528843Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528857Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528869Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528881Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528911Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528922Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528933Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528945Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528955Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.528966Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.528979Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.528989Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.529000Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.529013Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529022Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.529035Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.529047Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529056Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.529068Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.529080Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529090Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.529102Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.529114Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529124Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.529135Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.529148Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529158Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.529170Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.529159Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2026-04-24T21:32:10.529182Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529199Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.529198Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2026-04-24T21:32:10.529211Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.529219Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2026-04-24T21:32:10.529225Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529236Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.529232Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 }
[INFO] [stdout] 2026-04-24T21:32:10.529247Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.529260Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529270Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.529275Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.529283Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.529297Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529293Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.529307Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.529310Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.529320Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.529325Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529334Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=51
[INFO] [stdout] 2026-04-24T21:32:10.529343Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529346Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.529363Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.529378Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.529393Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2026-04-24T21:32:10.529408Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=67
[INFO] [stdout] 2026-04-24T21:32:10.529425Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=67
[INFO] [stdout] 2026-04-24T21:32:10.529443Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=67
[INFO] [stdout] 2026-04-24T21:32:10.529462Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529361Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529472Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.529486Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529478Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529496Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.529499Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.529510Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529515Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.529520Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.529533Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529530Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.529543Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.529545Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.529556Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529560Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.529567Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.529583Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529575Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529593Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.529599Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529615Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529617Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529633Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.529647Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529657Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.529643Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529669Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529680Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.529677Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529693Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529706Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.529720Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529704Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529730Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.529743Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529737Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529752Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.529765Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529762Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529775Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.529781Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529787Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529799Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.529810Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529797Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529848Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529865Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529886Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529918Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.529941Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.529819Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.529974Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.529984Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.529999Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.529993Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.530011Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=67
[INFO] [stdout] 2026-04-24T21:32:10.530015Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.530023Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.530037Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.530034Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.530050Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.530054Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530063Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2026-04-24T21:32:10.530069Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530077Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.530084Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530088Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=67
[INFO] [stdout] 2026-04-24T21:32:10.530098Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530105Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=51 future=106
[INFO] [stdout] 2026-04-24T21:32:10.530112Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530123Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=67 future=122
[INFO] [stdout] 2026-04-24T21:32:10.530128Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.530140Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=51 future=68
[INFO] [stdout] 2026-04-24T21:32:10.530153Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.530156Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=67
[INFO] [stdout] 2026-04-24T21:32:10.530169Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530173Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=83
[INFO] [stdout] 2026-04-24T21:32:10.530183Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.530189Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=83
[INFO] [stdout] 2026-04-24T21:32:10.530199Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.530208Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=83
[INFO] [stdout] 2026-04-24T21:32:10.530216Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.530226Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=83
[INFO] [stdout] 2026-04-24T21:32:10.530233Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.530244Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=67 future=122
[INFO] [stdout] 2026-04-24T21:32:10.530250Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530265Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=51 future=106
[INFO] [stdout] 2026-04-24T21:32:10.530268Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530288Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.530288Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530301Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.530303Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530312Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.530319Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530324Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.530335Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530337Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.530352Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.530350Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530367Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.530368Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530378Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.530383Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530391Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.530398Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530405Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.530414Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530417Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.530429Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530465Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530480Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530494Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530511Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530526Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530551Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530565Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530587Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530601Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530615Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530629Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530647Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530661Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530684Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530699Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530722Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530737Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.530756Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2026-04-24T21:32:10.530979Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192
[INFO] [stdout] 2026-04-24T21:32:10.531010Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.531022Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.531035Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1
[INFO] [stdout] 2026-04-24T21:32:10.531057Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.531083Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.531099Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.531122Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.531138Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.531151Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2026-04-24T21:32:10.531176Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40
[INFO] [stdout] 2026-04-24T21:32:10.531191Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56
[INFO] [stdout] 2026-04-24T21:32:10.531207Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2
[INFO] [stdout] 2026-04-24T21:32:10.531224Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2026-04-24T21:32:10.531250Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17
[INFO] [stdout] 2026-04-24T21:32:10.531266Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17
[INFO] [stdout] 2026-04-24T21:32:10.531288Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17
[INFO] [stdout] 2026-04-24T21:32:10.531304Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17
[INFO] [stdout] 2026-04-24T21:32:10.531332Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56
[INFO] [stdout] 2026-04-24T21:32:10.531348Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40
[INFO] [stdout] 2026-04-24T21:32:10.531374Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.531384Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.531403Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.531416Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.531425Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.531442Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.531454Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.531463Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.531474Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.531487Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.531508Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.531519Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.531540Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.531549Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.531560Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.531581Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.531590Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.531601Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.531612Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.531622Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.531646Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.531660Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.531678Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.531690Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.531702Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.531718Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.531729Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.531742Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.531753Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.531776Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.531788Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.531809Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.531822Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.531835Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.531853Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.531865Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.531878Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.531904Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.531918Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.531930Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.531939Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.531969Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.531982Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.531993Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.532005Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.532018Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.532028Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.532040Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.532052Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.532062Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.532074Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.532087Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.532097Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.532109Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.532121Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.532130Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.532142Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.532245Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.532258Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.532270Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.532284Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.532294Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.532306Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.532319Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.532329Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.532342Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.532355Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.532366Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.532378Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.532391Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.532400Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.532411Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.532422Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.532431Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.532443Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.532456Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.532466Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.532479Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.532492Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.532503Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.532515Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.532528Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.532538Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.532551Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.532564Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.532575Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.532587Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.532600Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.532611Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.532623Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.532636Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.532646Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.532657Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.532669Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17
[INFO] [stdout] 2026-04-24T21:32:10.532680Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.532692Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.532708Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.532723Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.532738Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21
[INFO] [stdout] 2026-04-24T21:32:10.532756Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21
[INFO] [stdout] 2026-04-24T21:32:10.532774Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21
[INFO] [stdout] 2026-04-24T21:32:10.532792Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21
[INFO] [stdout] 2026-04-24T21:32:10.532810Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27
[INFO] [stdout] 2026-04-24T21:32:10.532828Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27
[INFO] [stdout] 2026-04-24T21:32:10.532845Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26
[INFO] [stdout] 2026-04-24T21:32:10.532863Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38
[INFO] [stdout] 2026-04-24T21:32:10.530431Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.532921Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.532932Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.532944Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.532963Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.532972Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.532984Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] test utils::tests::test_addr ... 2026-04-24T21:32:10.532997Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.533023Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.533035Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.533046Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.533055Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.533069Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.533082Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.533092Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.533104Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.533117Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.533127Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.533137Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.533148Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.533157Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.533169Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.533182Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.533193Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.533205Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.533218Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.533229Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.533241Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.533255Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.533265Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.533278Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.533291Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.533302Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.533313Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.533326Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.533337Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.533350Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.533364Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=83
[INFO] [stdout] 2026-04-24T21:32:10.533376Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.533391Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.533404Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.533418Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2026-04-24T21:32:10.533434Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=21 future=87
[INFO] [stdout] 2026-04-24T21:32:10.533452Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=21 future=87
[INFO] [stdout] 2026-04-24T21:32:10.533471Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=21 future=87
[INFO] [stdout] 2026-04-24T21:32:10.533489Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=21 future=87
[INFO] [stdout] 2026-04-24T21:32:10.533507Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=36 future=102
[INFO] [stdout] 2026-04-24T21:32:10.533525Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=36 future=102
[INFO] [stdout] 2026-04-24T21:32:10.533642Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=106 future=117
[INFO] [stdout] 2026-04-24T21:32:10.533661Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=68 future=117
[INFO] [stdout] 2026-04-24T21:32:10.533677Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=23 future=89
[INFO] [stdout] 2026-04-24T21:32:10.533693Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=23 future=89
[INFO] [stdout] 2026-04-24T21:32:10.533711Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=42 future=108
[INFO] [stdout] 2026-04-24T21:32:10.533729Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=42 future=108
[INFO] [stdout] 2026-04-24T21:32:10.533749Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=106 future=117
[INFO] [stdout] 2026-04-24T21:32:10.533772Z DEBUG ramu_rs::controller: write request finished req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 83 }
[INFO] [stdout] 2026-04-24T21:32:10.533792Z 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] ok
[INFO] [stdout] test scheduler::tests::test ... ok
[INFO] [stdout] test test::test_memory_write ... ok
[INFO] [stdout] 2026-04-24T21:32:10.532881Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23
[INFO] [stdout] 2026-04-24T21:32:10.534187Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23
[INFO] [stdout] 2026-04-24T21:32:10.534211Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26
[INFO] [stdout] 2026-04-24T21:32:10.534231Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 } clk=17 req.finish_time=37
[INFO] [stdout] 2026-04-24T21:32:10.534252Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534264Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534277Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534291Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534301Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534312Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534324Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534334Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534345Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534358Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534369Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534381Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534395Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534406Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534418Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534430Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534440Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534453Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534468Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534478Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534489Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534502Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534512Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534523Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534536Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534546Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534559Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534571Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534580Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534591Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534603Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534612Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534624Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534638Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534648Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534660Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534673Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534683Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534694Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534707Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534718Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534731Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534744Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534754Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534767Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534780Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534792Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534804Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534817Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534828Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534840Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534852Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534862Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.534874Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.534887Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.534913Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.535039Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.535058Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535069Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.535081Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.535117Z DEBUG ramu_rs::test: recv req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 }
[INFO] [stdout] 2026-04-24T21:32:10.535141Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535153Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.535164Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.535176Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535186Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.535202Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.535215Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535235Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.535247Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.535270Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40
[INFO] [stdout] 2026-04-24T21:32:10.535281Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.535295Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.535310Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.535329Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2026-04-24T21:32:10.535344Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56
[INFO] [stdout] 2026-04-24T21:32:10.535373Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56
[INFO] [stdout] 2026-04-24T21:32:10.535391Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56
[INFO] [stdout] 2026-04-24T21:32:10.535411Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535420Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.535433Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535443Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.535455Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535465Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.535477Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535489Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.535506Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535516Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.535535Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535544Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.535556Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535565Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.535579Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535589Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.535601Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535612Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.535624Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535634Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.535647Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535662Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.535676Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535694Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.535707Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535716Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.535728Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535738Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.535750Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535760Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.535773Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.535783Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.535796Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56
[INFO] [stdout] 2026-04-24T21:32:10.535812Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.535828Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.535849Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.535865Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2026-04-24T21:32:10.535879Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.535905Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56
[INFO] [stdout] 2026-04-24T21:32:10.535923Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95
[INFO] [stdout] 2026-04-24T21:32:10.535939Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111
[INFO] [stdout] 2026-04-24T21:32:10.535978Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57
[INFO] [stdout] 2026-04-24T21:32:10.536010Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56
[INFO] [stdout] 2026-04-24T21:32:10.536049Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72
[INFO] [stdout] 2026-04-24T21:32:10.536066Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72
[INFO] [stdout] 2026-04-24T21:32:10.536089Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72
[INFO] [stdout] 2026-04-24T21:32:10.536121Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72
[INFO] [stdout] 2026-04-24T21:32:10.536140Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111
[INFO] [stdout] 2026-04-24T21:32:10.536170Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95
[INFO] [stdout] 2026-04-24T21:32:10.536190Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.536214Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.536227Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.536239Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.536248Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.536272Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.536287Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.536307Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.536405Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.536428Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.536439Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.536451Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.536469Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.536478Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.536490Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.536502Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.536523Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.536535Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.536555Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.536564Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.536576Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.536588Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.536609Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.536621Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.536633Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.536649Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.536660Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.536671Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.536680Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.536695Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.536707Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.536717Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.536727Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.536748Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.536759Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.536778Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.536791Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.536801Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.536818Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.536830Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.536840Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.536863Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.536875Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.536923Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.536941Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.536969Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2026-04-24T21:32:10.536981Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.537001Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2026-04-24T21:32:10.537014Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=72
[INFO] [stdout] 2026-04-24T21:32:10.537025Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.537039Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.537056Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.537070Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2026-04-24T21:32:10.537091Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=76
[INFO] [stdout] 2026-04-24T21:32:10.537109Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=76
[INFO] [stdout] 2026-04-24T21:32:10.537134Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=27 future=76
[INFO] [stdout] 2026-04-24T21:32:10.537152Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=27 future=76
[INFO] [stdout] 2026-04-24T21:32:10.537175Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=21 future=91
[INFO] [stdout] 2026-04-24T21:32:10.537202Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=21 future=91
[INFO] [stdout] 2026-04-24T21:32:10.537230Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=95 future=106
[INFO] [stdout] 2026-04-24T21:32:10.537249Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=57 future=106
[INFO] [stdout] 2026-04-24T21:32:10.537272Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=78
[INFO] [stdout] 2026-04-24T21:32:10.537290Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=78
[INFO] [stdout] 2026-04-24T21:32:10.537319Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=23 future=97
[INFO] [stdout] 2026-04-24T21:32:10.537347Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=23 future=97
[INFO] [stdout] 2026-04-24T21:32:10.537376Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=95 future=106
[INFO] [stdout] 2026-04-24T21:32:10.537396Z DEBUG ramu_rs::controller: write request finished req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 72 }
[INFO] [stdout] 2026-04-24T21:32:10.537419Z DEBUG ramu_rs::test: recv req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 72 }
[INFO] [stdout] test test::test_memory_read_and_write ... ok
[INFO] [stdout] 2026-04-24T21:32:10.537885Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2026-04-24T21:32:10.537947Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2026-04-24T21:32:10.537968Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2026-04-24T21:32:10.537982Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 }
[INFO] [stdout] 2026-04-24T21:32:10.538025Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538042Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538057Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538070Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538089Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538106Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538124Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538139Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538153Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538167Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538181Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538202Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538217Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538239Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538256Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538275Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538306Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538332Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538366Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538393Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538411Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538427Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538460Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538477Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538497Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538513Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538527Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538541Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538559Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538579Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538601Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538631Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538646Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538660Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538675Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538689Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538703Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538726Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538742Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538756Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538777Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538792Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538808Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.538823Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538837Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538852Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538866Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538880Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538914Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538928Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538942Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538956Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538971Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538984Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.538997Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539010Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539024Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539039Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539052Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539066Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539080Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539095Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539108Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539123Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539140Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539154Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539169Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539182Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539202Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539217Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539231Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539246Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.539262Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2026-04-24T21:32:10.539517Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=1
[INFO] [stdout] 2026-04-24T21:32:10.539581Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 0]
[INFO] [stdout] 2026-04-24T21:32:10.539618Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 0
[INFO] [stdout] 2026-04-24T21:32:10.539635Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=65
[INFO] [stdout] 2026-04-24T21:32:10.539677Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 1]
[INFO] [stdout] 2026-04-24T21:32:10.539702Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 64
[INFO] [stdout] 2026-04-24T21:32:10.539718Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=257
[INFO] [stdout] 2026-04-24T21:32:10.539737Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 4]
[INFO] [stdout] 2026-04-24T21:32:10.539755Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 256
[INFO] [stdout] test ddr4::tests::test_address ... ok
[INFO] [stdout] 2026-04-24T21:32:10.551123Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2026-04-24T21:32:10.551182Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2026-04-24T21:32:10.551205Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2026-04-24T21:32:10.551219Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 }
[INFO] [stdout] 2026-04-24T21:32:10.551276Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.551304Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.551319Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.551343Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.551368Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.551396Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.551425Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.551456Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.551487Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.551518Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.551538Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.551565Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.551583Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.551616Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.551636Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.551656Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.551689Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.551729Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.551759Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.551784Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.551802Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.551817Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.551846Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.551863Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.551886Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.553043Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.553072Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.553089Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.553107Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.553128Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.553476Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.553504Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.554285Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.554310Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.554326Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.554342Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.555114Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.555146Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.555163Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.555178Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.555194Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.555210Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.557018Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2026-04-24T21:32:10.557045Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557062Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557077Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557093Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557108Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557123Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557159Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557175Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557191Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557205Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557220Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557235Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557251Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557266Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557281Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557296Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557312Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557329Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557344Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557359Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557378Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557393Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557408Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557424Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557440Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557455Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557470Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557486Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557501Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2026-04-24T21:32:10.557517Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2026-04-24T21:32:10.557623Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192
[INFO] [stdout] 2026-04-24T21:32:10.557643Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.557656Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.557672Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1
[INFO] [stdout] 2026-04-24T21:32:10.557685Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.557699Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.557713Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.557727Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.557742Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.557753Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2026-04-24T21:32:10.557771Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40
[INFO] [stdout] 2026-04-24T21:32:10.557789Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56
[INFO] [stdout] 2026-04-24T21:32:10.557809Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2
[INFO] [stdout] 2026-04-24T21:32:10.557827Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2026-04-24T21:32:10.557845Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17
[INFO] [stdout] 2026-04-24T21:32:10.557862Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17
[INFO] [stdout] 2026-04-24T21:32:10.557879Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17
[INFO] [stdout] 2026-04-24T21:32:10.557921Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17
[INFO] [stdout] 2026-04-24T21:32:10.557939Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56
[INFO] [stdout] 2026-04-24T21:32:10.557956Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40
[INFO] [stdout] 2026-04-24T21:32:10.557976Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.557987Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.557999Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.558013Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558023Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.558035Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.558048Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558059Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.558072Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.558085Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558096Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.558108Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.558122Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558132Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.558147Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.558160Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558170Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.558183Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.558196Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558206Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.558219Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.558232Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558243Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.558255Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.558269Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558280Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.558293Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.558305Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558315Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.558328Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.558341Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558352Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.558364Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.558377Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558388Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.558400Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.558413Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558424Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.558437Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.558451Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558462Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.558475Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.558491Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558503Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.558516Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.558530Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558541Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.558554Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.558569Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558580Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.558593Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.558607Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558618Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.558631Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.558646Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558657Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.558671Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.558685Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558696Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.558709Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.558724Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558735Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.558748Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.558762Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558773Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.558787Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.558801Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558813Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.558827Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.558841Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.558854Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.558867Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.558882Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.559485Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.559532Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.560058Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.560098Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.560116Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.560133Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.560146Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.560159Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.560173Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.560184Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.560198Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.560213Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.560224Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.569086Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.569497Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.569589Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.569622Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.569674Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.569689Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2026-04-24T21:32:10.569702Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.569729Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17
[INFO] [stdout] 2026-04-24T21:32:10.569756Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.569773Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.569788Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.569800Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.569831Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21
[INFO] [stdout] 2026-04-24T21:32:10.569853Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21
[INFO] [stdout] 2026-04-24T21:32:10.569878Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21
[INFO] [stdout] 2026-04-24T21:32:10.570005Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21
[INFO] [stdout] 2026-04-24T21:32:10.570040Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27
[INFO] [stdout] 2026-04-24T21:32:10.570057Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27
[INFO] [stdout] 2026-04-24T21:32:10.570081Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26
[INFO] [stdout] 2026-04-24T21:32:10.570100Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38
[INFO] [stdout] 2026-04-24T21:32:10.570122Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23
[INFO] [stdout] 2026-04-24T21:32:10.570145Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23
[INFO] [stderr] error: test failed, to rerun pass `--lib`
[INFO] [stdout] 2026-04-24T21:32:10.570197Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26
[INFO] [stdout] 2026-04-24T21:32:10.570247Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 } clk=17 req.finish_time=37
[INFO] [stdout] 2026-04-24T21:32:10.570316Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.570332Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.570353Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.570365Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.570376Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.570387Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.570399Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.570410Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.570423Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.570435Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.570446Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.570458Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.570475Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.570485Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.570496Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.570508Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.570519Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.570531Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.570542Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.570553Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.570563Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.570577Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.570587Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.570617Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.570629Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.570637Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.570647Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.570657Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.570666Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.570676Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.570687Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.570696Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.570710Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.570723Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.570734Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.570745Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.570757Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.570768Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.570779Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.570791Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.570802Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.570816Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.570833Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.570845Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.570857Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.570869Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.570880Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.571524Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.571620Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.571650Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.571670Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.571689Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.571702Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.571716Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.571732Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.571743Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.571754Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.571774Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.571784Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.571797Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.572028Z DEBUG ramu_rs::test: recv req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 }
[INFO] [stdout] 2026-04-24T21:32:10.572107Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572125Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.572143Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.572158Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572171Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.572182Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.572194Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572205Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.572216Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2026-04-24T21:32:10.572230Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40
[INFO] [stdout] 2026-04-24T21:32:10.572245Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.572260Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.572295Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.572310Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2026-04-24T21:32:10.572333Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56
[INFO] [stdout] 2026-04-24T21:32:10.572349Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56
[INFO] [stdout] 2026-04-24T21:32:10.572371Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56
[INFO] [stdout] 2026-04-24T21:32:10.572397Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572409Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.572421Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572431Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.572442Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572450Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.572461Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572469Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.572480Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572489Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.572502Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572511Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.572522Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572531Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.572542Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572552Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.572563Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572573Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.572586Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572596Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.572626Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572635Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.572645Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572654Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.572664Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572674Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.572685Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572694Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.572706Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572716Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.572729Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.572739Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2026-04-24T21:32:10.572759Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56
[INFO] [stdout] 2026-04-24T21:32:10.572776Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.572789Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.572802Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.572815Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2026-04-24T21:32:10.572831Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.572851Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56
[INFO] [stdout] 2026-04-24T21:32:10.572869Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95
[INFO] [stdout] 2026-04-24T21:32:10.572884Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111
[INFO] [stdout] 2026-04-24T21:32:10.573025Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57
[INFO] [stdout] 2026-04-24T21:32:10.573052Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56
[INFO] [stdout] 2026-04-24T21:32:10.573089Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72
[INFO] [stdout] 2026-04-24T21:32:10.573109Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72
[INFO] [stdout] 2026-04-24T21:32:10.573126Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72
[INFO] [stdout] 2026-04-24T21:32:10.573142Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72
[INFO] [stdout] 2026-04-24T21:32:10.573157Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111
[INFO] [stdout] 2026-04-24T21:32:10.573173Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95
[INFO] [stdout] 2026-04-24T21:32:10.573202Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.573213Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.573226Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.573238Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.573248Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.573260Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.573272Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.573281Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.573292Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.573302Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.573312Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.573323Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.573334Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.573343Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.573355Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.573367Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.573377Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.573395Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.573408Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.573417Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.573430Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.573441Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.573451Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.573462Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.573474Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.573483Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.573495Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.573506Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.573516Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.573528Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.573540Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.573548Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.573562Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.573577Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.573587Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.573597Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.573608Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.573619Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.573630Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.573642Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.573651Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.573662Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.573674Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.573683Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.573694Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.573718Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2026-04-24T21:32:10.573732Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2026-04-24T21:32:10.573745Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2026-04-24T21:32:10.573766Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=72
[INFO] [stdout] 2026-04-24T21:32:10.573782Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.573794Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.573806Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2026-04-24T21:32:10.573818Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2026-04-24T21:32:10.573836Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=21 future=76
[INFO] [stdout] 2026-04-24T21:32:10.573852Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=21 future=76
[INFO] [stdout] 2026-04-24T21:32:10.573873Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=21 future=76
[INFO] [stdout] 2026-04-24T21:32:10.574018Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=21 future=76
[INFO] [stdout] 2026-04-24T21:32:10.574065Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=27 future=82
[INFO] [stdout] 2026-04-24T21:32:10.574083Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=27 future=82
[INFO] [stdout] 2026-04-24T21:32:10.574104Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=95 future=81
[INFO] [stdout] 2026-04-24T21:32:10.574122Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=57 future=93
[INFO] [stdout] 2026-04-24T21:32:10.574143Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=23 future=78
[INFO] [stdout] 2026-04-24T21:32:10.574163Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=23 future=78
[INFO] [stdout] 2026-04-24T21:32:10.574183Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=95 future=81
[INFO] [stdout] 2026-04-24T21:32:10.574216Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 92 } clk=72 req.finish_time=92
[INFO] [stdout] 2026-04-24T21:32:10.574254Z 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] test controller::tests::test_controller_simple_read ... FAILED
[INFO] [stdout] 
[INFO] [stdout] failures:
[INFO] [stdout] 
[INFO] [stdout] ---- controller::tests::test_controller_simple_read stdout ----
[INFO] [stdout] 
[INFO] [stdout] thread 'controller::tests::test_controller_simple_read' (16) panicked at src/controller.rs:300:9:
[INFO] [stdout] assertion failed: controller.finished_queue.is_empty()
[INFO] [stdout] stack backtrace:
[INFO] [stdout]    0:     0x604b7ecbae3a - std[e28293b1aa0f68bd]::backtrace_rs::backtrace::libunwind::trace
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/../../backtrace/src/backtrace/libunwind.rs:117:9
[INFO] [stdout]    1:     0x604b7ecbae3a - std[e28293b1aa0f68bd]::backtrace_rs::backtrace::trace_unsynchronized::<std[e28293b1aa0f68bd]::sys::backtrace::_print_fmt::{closure#1}>
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/../../backtrace/src/backtrace/mod.rs:66:14
[INFO] [stdout]    2:     0x604b7ecbae3a - std[e28293b1aa0f68bd]::sys::backtrace::_print_fmt
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/sys/backtrace.rs:74:9
[INFO] [stdout]    3:     0x604b7ecbae3a - <<std[e28293b1aa0f68bd]::sys::backtrace::BacktraceLock>::print::DisplayBacktrace as core[c1f1a4ba060b9bfa]::fmt::Display>::fmt
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/sys/backtrace.rs:44:26
[INFO] [stdout]    4:     0x604b7ecd013a - <core[c1f1a4ba060b9bfa]::fmt::rt::Argument>::fmt
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/core/src/fmt/rt.rs:152:76
[INFO] [stdout]    5:     0x604b7ecd013a - core[c1f1a4ba060b9bfa]::fmt::write
[INFO] [stdout]    6:     0x604b7ecbf772 - std[e28293b1aa0f68bd]::io::default_write_fmt::<alloc[fdfd2bd8633a6659]::vec::Vec<u8>>
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/io/mod.rs:639:11
[INFO] [stdout]    7:     0x604b7ecbf772 - <alloc[fdfd2bd8633a6659]::vec::Vec<u8> as std[e28293b1aa0f68bd]::io::Write>::write_fmt
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/io/mod.rs:1994:13
[INFO] [stdout]    8:     0x604b7ec99e8f - <std[e28293b1aa0f68bd]::sys::backtrace::BacktraceLock>::print
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/sys/backtrace.rs:47:9
[INFO] [stdout]    9:     0x604b7ec99e8f - std[e28293b1aa0f68bd]::panicking::default_hook::{closure#0}
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:292:27
[INFO] [stdout]   10:     0x604b7ecb3229 - std[e28293b1aa0f68bd]::panicking::default_hook
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:316:9
[INFO] [stdout]   11:     0x604b7eab314c - <alloc[fdfd2bd8633a6659]::boxed::Box<dyn for<'a, 'b> core[c1f1a4ba060b9bfa]::ops::function::Fn<(&'a std[e28293b1aa0f68bd]::panic::PanicHookInfo<'b>,), Output = ()> + core[c1f1a4ba060b9bfa]::marker::Sync + core[c1f1a4ba060b9bfa]::marker::Send> as core[c1f1a4ba060b9bfa]::ops::function::Fn<(&std[e28293b1aa0f68bd]::panic::PanicHookInfo,)>>::call
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/alloc/src/boxed.rs:2254:9
[INFO] [stdout]   12:     0x604b7eab314c - test[273d7611820c9051]::test_main_with_exit_callback::<test[273d7611820c9051]::test_main::{closure#0}>::{closure#0}
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/test/src/lib.rs:145:21
[INFO] [stdout]   13:     0x604b7ecb33e2 - <alloc[fdfd2bd8633a6659]::boxed::Box<dyn for<'a, 'b> core[c1f1a4ba060b9bfa]::ops::function::Fn<(&'a std[e28293b1aa0f68bd]::panic::PanicHookInfo<'b>,), Output = ()> + core[c1f1a4ba060b9bfa]::marker::Sync + core[c1f1a4ba060b9bfa]::marker::Send> as core[c1f1a4ba060b9bfa]::ops::function::Fn<(&std[e28293b1aa0f68bd]::panic::PanicHookInfo,)>>::call
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/alloc/src/boxed.rs:2254:9
[INFO] [stdout]   14:     0x604b7ecb33e2 - std[e28293b1aa0f68bd]::panicking::panic_with_hook
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:833:13
[INFO] [stdout]   15:     0x604b7ec99f7a - std[e28293b1aa0f68bd]::panicking::panic_handler::{closure#0}
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:691:13
[INFO] [stdout]   16:     0x604b7ec918b9 - std[e28293b1aa0f68bd]::sys::backtrace::__rust_end_short_backtrace::<std[e28293b1aa0f68bd]::panicking::panic_handler::{closure#0}, !>
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/sys/backtrace.rs:182:18
[INFO] [stdout]   17:     0x604b7ec9ac5d - __rustc[b7974e8690430dd9]::rust_begin_unwind
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:689:5
[INFO] [stdout]   18:     0x604b7ecd0a9c - core[c1f1a4ba060b9bfa]::panicking::panic_fmt
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/core/src/panicking.rs:80:14
[INFO] [stdout]   19:     0x604b7ecd0a62 - core[c1f1a4ba060b9bfa]::panicking::panic
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/core/src/panicking.rs:150:5
[INFO] [stdout]   20:     0x604b7ea9b90f - ramu_rs::controller::tests::test_controller_simple_read::h88bad8ee534c0479
[INFO] [stdout]                                at /opt/rustwide/workdir/src/controller.rs:300:9
[INFO] [stdout]   21:     0x604b7ea9ba07 - ramu_rs::controller::tests::test_controller_simple_read::{{closure}}::h65d5f937f0207ffb
[INFO] [stdout]                                at /opt/rustwide/workdir/src/controller.rs:277:37
[INFO] [stdout]   22:     0x604b7ea998f6 - core::ops::function::FnOnce::call_once::h8c7260dbf24cfdf9
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/core/src/ops/function.rs:250:5
[INFO] [stdout]   23:     0x604b7eaa722b - <fn() -> core[c1f1a4ba060b9bfa]::result::Result<(), alloc[fdfd2bd8633a6659]::string::String> as core[c1f1a4ba060b9bfa]::ops::function::FnOnce<()>>::call_once
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/core/src/ops/function.rs:250:5
[INFO] [stdout]   24:     0x604b7eaa722b - test[273d7611820c9051]::__rust_begin_short_backtrace::<core[c1f1a4ba060b9bfa]::result::Result<(), alloc[fdfd2bd8633a6659]::string::String>, fn() -> core[c1f1a4ba060b9bfa]::result::Result<(), alloc[fdfd2bd8633a6659]::string::String>>
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/test/src/lib.rs:663:18
[INFO] [stdout]   25:     0x604b7eab3c1b - test[273d7611820c9051]::run_test_in_process::{closure#0}
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/test/src/lib.rs:686:74
[INFO] [stdout]   26:     0x604b7eab3c1b - <core[c1f1a4ba060b9bfa]::panic::unwind_safe::AssertUnwindSafe<test[273d7611820c9051]::run_test_in_process::{closure#0}> as core[c1f1a4ba060b9bfa]::ops::function::FnOnce<()>>::call_once
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/core/src/panic/unwind_safe.rs:274:9
[INFO] [stdout]   27:     0x604b7eab3c1b - std[e28293b1aa0f68bd]::panicking::catch_unwind::do_call::<core[c1f1a4ba060b9bfa]::panic::unwind_safe::AssertUnwindSafe<test[273d7611820c9051]::run_test_in_process::{closure#0}>, core[c1f1a4ba060b9bfa]::result::Result<(), alloc[fdfd2bd8633a6659]::string::String>>
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:581:40
[INFO] [stdout]   28:     0x604b7eab3c1b - std[e28293b1aa0f68bd]::panicking::catch_unwind::<core[c1f1a4ba060b9bfa]::result::Result<(), alloc[fdfd2bd8633a6659]::string::String>, core[c1f1a4ba060b9bfa]::panic::unwind_safe::AssertUnwindSafe<test[273d7611820c9051]::run_test_in_process::{closure#0}>>
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:544:19
[INFO] [stdout]   29:     0x604b7eab3c1b - std[e28293b1aa0f68bd]::panic::catch_unwind::<core[c1f1a4ba060b9bfa]::panic::unwind_safe::AssertUnwindSafe<test[273d7611820c9051]::run_test_in_process::{closure#0}>, core[c1f1a4ba060b9bfa]::result::Result<(), alloc[fdfd2bd8633a6659]::string::String>>
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panic.rs:359:14
[INFO] [stdout]   30:     0x604b7eab3c1b - test[273d7611820c9051]::run_test_in_process
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/test/src/lib.rs:686:27
[INFO] [stdout]   31:     0x604b7eab3c1b - test[273d7611820c9051]::run_test::{closure#0}
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/test/src/lib.rs:607:43
[INFO] [stdout]   32:     0x604b7eaaf334 - test[273d7611820c9051]::run_test::{closure#1}
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/test/src/lib.rs:637:41
[INFO] [stdout]   33:     0x604b7eaaf334 - std[e28293b1aa0f68bd]::sys::backtrace::__rust_begin_short_backtrace::<test[273d7611820c9051]::run_test::{closure#1}, ()>
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/sys/backtrace.rs:166:18
[INFO] [stdout]   34:     0x604b7eab6822 - std[e28293b1aa0f68bd]::thread::lifecycle::spawn_unchecked::<test[273d7611820c9051]::run_test::{closure#1}, ()>::{closure#1}::{closure#0}
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/thread/lifecycle.rs:91:13
[INFO] [stdout]   35:     0x604b7eab6822 - <core[c1f1a4ba060b9bfa]::panic::unwind_safe::AssertUnwindSafe<std[e28293b1aa0f68bd]::thread::lifecycle::spawn_unchecked<test[273d7611820c9051]::run_test::{closure#1}, ()>::{closure#1}::{closure#0}> as core[c1f1a4ba060b9bfa]::ops::function::FnOnce<()>>::call_once
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/core/src/panic/unwind_safe.rs:274:9
[INFO] [stdout]   36:     0x604b7eab6822 - std[e28293b1aa0f68bd]::panicking::catch_unwind::do_call::<core[c1f1a4ba060b9bfa]::panic::unwind_safe::AssertUnwindSafe<std[e28293b1aa0f68bd]::thread::lifecycle::spawn_unchecked<test[273d7611820c9051]::run_test::{closure#1}, ()>::{closure#1}::{closure#0}>, ()>
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:581:40
[INFO] [stdout]   37:     0x604b7eab6822 - std[e28293b1aa0f68bd]::panicking::catch_unwind::<(), core[c1f1a4ba060b9bfa]::panic::unwind_safe::AssertUnwindSafe<std[e28293b1aa0f68bd]::thread::lifecycle::spawn_unchecked<test[273d7611820c9051]::run_test::{closure#1}, ()>::{closure#1}::{closure#0}>>
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panicking.rs:544:19
[INFO] [stdout]   38:     0x604b7eab6822 - std[e28293b1aa0f68bd]::panic::catch_unwind::<core[c1f1a4ba060b9bfa]::panic::unwind_safe::AssertUnwindSafe<std[e28293b1aa0f68bd]::thread::lifecycle::spawn_unchecked<test[273d7611820c9051]::run_test::{closure#1}, ()>::{closure#1}::{closure#0}>, ()>
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/panic.rs:359:14
[INFO] [stdout]   39:     0x604b7eab6822 - std[e28293b1aa0f68bd]::thread::lifecycle::spawn_unchecked::<test[273d7611820c9051]::run_test::{closure#1}, ()>::{closure#1}
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/thread/lifecycle.rs:89:26
[INFO] [stdout]   40:     0x604b7eab6822 - <std[e28293b1aa0f68bd]::thread::lifecycle::spawn_unchecked<test[273d7611820c9051]::run_test::{closure#1}, ()>::{closure#1} as core[c1f1a4ba060b9bfa]::ops::function::FnOnce<()>>::call_once::{shim:vtable#0}
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/core/src/ops/function.rs:250:5
[INFO] [stdout]   41:     0x604b7ecba71f - <alloc[fdfd2bd8633a6659]::boxed::Box<dyn core[c1f1a4ba060b9bfa]::ops::function::FnOnce<(), Output = ()> + core[c1f1a4ba060b9bfa]::marker::Send> as core[c1f1a4ba060b9bfa]::ops::function::FnOnce<()>>::call_once
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/alloc/src/boxed.rs:2240:9
[INFO] [stdout]   42:     0x604b7ecba71f - <std[e28293b1aa0f68bd]::sys::thread::unix::Thread>::new::thread_start
[INFO] [stdout]                                at /rustc/59807616e1fa2540724bfbac14d7976d7e4a3860/library/std/src/sys/thread/unix.rs:118:17
[INFO] [stdout]   43:     0x7b5064f56aa4 - <unknown>
[INFO] [stdout]   44:     0x7b5064fe3a64 - clone
[INFO] [stdout]   45:                0x0 - <unknown>
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] failures:
[INFO] [stdout]     controller::tests::test_controller_simple_read
[INFO] [stdout] 
[INFO] [stdout] test result: FAILED. 6 passed; 1 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.06s
[INFO] [stdout] 
[INFO] running `Command { std: "docker" "inspect" "75942097cc80c3f907368161fa358e63b4642003dd5db7287555617796989096", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "75942097cc80c3f907368161fa358e63b4642003dd5db7287555617796989096", kill_on_drop: false }`
[INFO] [stdout] 75942097cc80c3f907368161fa358e63b4642003dd5db7287555617796989096