[INFO] fetching crate ramu_rs 0.1.1...
[INFO] testing ramu_rs-0.1.1 against try#2440211fe03bc45c89b6dc1a3df18382ce91e32b for pr-146098-1
[INFO] extracting crate ramu_rs 0.1.1 into /workspace/builds/worker-2-tc2/source
[INFO] started tweaking crates.io crate ramu_rs 0.1.1
[INFO] finished tweaking crates.io crate ramu_rs 0.1.1
[INFO] tweaked toml for crates.io crate ramu_rs 0.1.1 written to /workspace/builds/worker-2-tc2/source/Cargo.toml
[INFO] validating manifest of crates.io crate ramu_rs 0.1.1 on toolchain 2440211fe03bc45c89b6dc1a3df18382ce91e32b
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+2440211fe03bc45c89b6dc1a3df18382ce91e32b" "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" "+2440211fe03bc45c89b6dc1a3df18382ce91e32b" "generate-lockfile" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Updating crates.io index
[INFO] [stderr]      Locking 73 packages to latest compatible versions
[INFO] [stderr]       Adding enum-as-inner v0.5.1 (available: v0.6.1)
[INFO] [stderr]       Adding num_enum v0.5.11 (available: v0.7.4)
[INFO] [stderr]       Adding toml v0.5.11 (available: v0.9.7)
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+2440211fe03bc45c89b6dc1a3df18382ce91e32b" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+2440211fe03bc45c89b6dc1a3df18382ce91e32b" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] 33f48e6f60123bd0487fb20d4901328da8c33d07e4d9ab6568dcba1369d008c4
[INFO] running `Command { std: "docker" "start" "-a" "33f48e6f60123bd0487fb20d4901328da8c33d07e4d9ab6568dcba1369d008c4", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "33f48e6f60123bd0487fb20d4901328da8c33d07e4d9ab6568dcba1369d008c4", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "33f48e6f60123bd0487fb20d4901328da8c33d07e4d9ab6568dcba1369d008c4", kill_on_drop: false }`
[INFO] [stdout] 33f48e6f60123bd0487fb20d4901328da8c33d07e4d9ab6568dcba1369d008c4
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+2440211fe03bc45c89b6dc1a3df18382ce91e32b" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] c4b458824a2c7a0df92e6123f95f285d0a56876e7ecb9d2f77c5f0a044924bed
[INFO] running `Command { std: "docker" "start" "-a" "c4b458824a2c7a0df92e6123f95f285d0a56876e7ecb9d2f77c5f0a044924bed", kill_on_drop: false }`
[INFO] [stderr]    Compiling proc-macro2 v1.0.101
[INFO] [stderr]    Compiling once_cell v1.21.3
[INFO] [stderr]    Compiling shlex v1.3.0
[INFO] [stderr]    Compiling equivalent v1.0.2
[INFO] [stderr]    Compiling hashbrown v0.16.0
[INFO] [stderr]    Compiling find-msvc-tools v0.1.2
[INFO] [stderr]    Compiling syn v1.0.109
[INFO] [stderr]    Compiling toml_datetime v0.6.11
[INFO] [stderr]    Compiling winnow v0.5.40
[INFO] [stderr]    Compiling rustversion v1.0.22
[INFO] [stderr]    Compiling regex-syntax v0.8.6
[INFO] [stderr]    Compiling cxxbridge-flags v1.0.186
[INFO] [stderr]    Compiling lazy_static v1.5.0
[INFO] [stderr]    Compiling cfg-if v1.0.3
[INFO] [stderr]    Compiling pin-project-lite v0.2.16
[INFO] [stderr]    Compiling log v0.4.28
[INFO] [stderr]    Compiling thread_local v1.1.9
[INFO] [stderr]    Compiling sharded-slab v0.1.7
[INFO] [stderr]    Compiling foldhash v0.2.0
[INFO] [stderr]    Compiling heck v0.4.1
[INFO] [stderr]    Compiling nu-ansi-term v0.50.1
[INFO] [stderr]    Compiling tracing-core v0.1.34
[INFO] [stderr]    Compiling cc v1.2.39
[INFO] [stderr]    Compiling smallvec v1.15.1
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling indexmap v2.11.4
[INFO] [stderr]    Compiling quote v1.0.41
[INFO] [stderr]    Compiling regex-automata v0.4.11
[INFO] [stderr]    Compiling syn v2.0.106
[INFO] [stderr]    Compiling link-cplusplus v1.0.12
[INFO] [stderr]    Compiling cxx v1.0.186
[INFO] [stderr]    Compiling toml_edit v0.19.15
[INFO] [stderr]    Compiling enum-as-inner v0.5.1
[INFO] [stderr]    Compiling proc-macro-crate v1.3.1
[INFO] [stderr]    Compiling matchers v0.2.0
[INFO] [stderr]    Compiling num_enum_derive v0.5.11
[INFO] [stderr]    Compiling num_enum v0.5.11
[INFO] [stderr]    Compiling tracing-attributes v0.1.30
[INFO] [stderr]    Compiling serde_derive v1.0.228
[INFO] [stderr]    Compiling cxxbridge-macro v1.0.186
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling tracing-subscriber v0.3.20
[INFO] [stderr]    Compiling serde v1.0.228
[INFO] [stderr]    Compiling toml v0.5.11
[INFO] [stderr]    Compiling ramu_rs v0.1.1 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 24.94s
[INFO] running `Command { std: "docker" "inspect" "c4b458824a2c7a0df92e6123f95f285d0a56876e7ecb9d2f77c5f0a044924bed", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "c4b458824a2c7a0df92e6123f95f285d0a56876e7ecb9d2f77c5f0a044924bed", kill_on_drop: false }`
[INFO] [stdout] c4b458824a2c7a0df92e6123f95f285d0a56876e7ecb9d2f77c5f0a044924bed
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+2440211fe03bc45c89b6dc1a3df18382ce91e32b" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 228fbeb60af54c2a0563aaeefd3a5a7abebf16c5f2542db39d83913fd294e574
[INFO] running `Command { std: "docker" "start" "-a" "228fbeb60af54c2a0563aaeefd3a5a7abebf16c5f2542db39d83913fd294e574", 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.08s
[INFO] running `Command { std: "docker" "inspect" "228fbeb60af54c2a0563aaeefd3a5a7abebf16c5f2542db39d83913fd294e574", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "228fbeb60af54c2a0563aaeefd3a5a7abebf16c5f2542db39d83913fd294e574", kill_on_drop: false }`
[INFO] [stdout] 228fbeb60af54c2a0563aaeefd3a5a7abebf16c5f2542db39d83913fd294e574
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:e90291280db7d1fac5b66fc6dad9f9662629e7365a55743daf9bdf73ebc4ea79" "/opt/rustwide/cargo-home/bin/cargo" "+2440211fe03bc45c89b6dc1a3df18382ce91e32b" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 3a8c5057b42020320c8039603addce30a9f3e6d92a548418ff1627e983b23e74
[INFO] running `Command { std: "docker" "start" "-a" "3a8c5057b42020320c8039603addce30a9f3e6d92a548418ff1627e983b23e74", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.10s
[INFO] [stdout] 
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/ramu_rs-68ae99c1bb8f162d)
[INFO] [stdout] running 8 tests
[INFO] [stdout] 2025-10-01T17:40:44.840817Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2025-10-01T17:40:44.841816Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2025-10-01T17:40:44.841890Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2025-10-01T17:40:44.841251Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2025-10-01T17:40:44.841958Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2025-10-01T17:40:44.842012Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2025-10-01T17:40:44.841976Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] test config::tests::dum_config ... ignored
[INFO] [stdout] 2025-10-01T17:40:44.842040Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 }
[INFO] [stdout] 2025-10-01T17:40:44.842204Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2025-10-01T17:40:44.842343Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2025-10-01T17:40:44.842472Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2025-10-01T17:40:44.842516Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 }
[INFO] [stdout] 2025-10-01T17:40:44.842055Z  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] test scheduler::tests::test ... ok2025-10-01T17:40:44.842668Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.842266Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.842318Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2025-10-01T17:40:44.842610Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.842721Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2025-10-01T17:40:44.842738Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2025-10-01T17:40:44.842752Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.842763Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.842770Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 }
[INFO] [stdout] 2025-10-01T17:40:44.842791Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.842807Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.842814Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.842845Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.842863Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.842873Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.842893Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.842903Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.842923Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.842934Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.842953Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.842963Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.842981Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.842994Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843016Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843031Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843053Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843066Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843095Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843112Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843140Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843154Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843186Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843197Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843223Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843236Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843259Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843270Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843292Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843304Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843328Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843342Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843366Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843380Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843402Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843414Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843436Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843462Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843485Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843514Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843529Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843550Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843563Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843585Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843601Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.843620Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843630Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843648Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843658Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843676Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843686Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843708Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843718Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843738Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843748Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843759Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843779Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843791Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843811Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843823Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843844Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843854Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843878Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843888Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843906Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843917Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843935Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843946Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843965Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843975Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.843985Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.844003Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.844013Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.844033Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.844050Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2025-10-01T17:40:44.844176Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192
[INFO] [stdout] 2025-10-01T17:40:44.844207Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.844221Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.844246Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1
[INFO] [stdout] 2025-10-01T17:40:44.844258Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.844284Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.844296Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.844314Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.844327Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.844340Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-10-01T17:40:44.844363Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40
[INFO] [stdout] 2025-10-01T17:40:44.844376Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56
[INFO] [stdout] 2025-10-01T17:40:44.844398Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2
[INFO] [stdout] 2025-10-01T17:40:44.844411Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-10-01T17:40:44.844432Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17
[INFO] [stdout] 2025-10-01T17:40:44.844459Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17
[INFO] [stdout] 2025-10-01T17:40:44.844473Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17
[INFO] [stdout] 2025-10-01T17:40:44.844498Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17
[INFO] [stdout] 2025-10-01T17:40:44.844509Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56
[INFO] [stdout] 2025-10-01T17:40:44.844531Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40
[INFO] [stdout] 2025-10-01T17:40:44.844550Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.844571Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.844583Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.844607Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.844616Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.844637Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.844648Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.844667Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.844677Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.844703Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.844711Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.844732Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.844743Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.844751Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.844769Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.844778Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.844786Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.844806Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.844817Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.844836Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.844846Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.844866Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.844875Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.844894Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.844904Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.844924Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.844933Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.844953Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.844960Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.844969Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.844998Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845005Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.845014Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.845032Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845040Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.845059Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.845067Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845075Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.845083Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.845104Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845111Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.845120Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.845142Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845149Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.845158Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.845185Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845192Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.845200Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.845221Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845228Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.845237Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.845257Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845264Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.845273Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.845294Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845301Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.845310Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.845334Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845344Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.845368Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.845379Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845399Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.845410Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.845421Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845485Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.845506Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.845519Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845528Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.845549Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.845560Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845579Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.845589Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.845600Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845620Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.845633Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.845653Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845664Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.845687Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.845699Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845708Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.845719Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.845741Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845750Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.845770Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.845781Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845791Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.845812Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.845824Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845833Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.845858Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.845870Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.845884Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.845893Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.845915Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17
[INFO] [stdout] 2025-10-01T17:40:44.845925Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.845935Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.845946Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.845966Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.845978Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21
[INFO] [stdout] 2025-10-01T17:40:44.845991Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21
[INFO] [stdout] 2025-10-01T17:40:44.846015Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21
[INFO] [stdout] 2025-10-01T17:40:44.846029Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21
[INFO] [stdout] 2025-10-01T17:40:44.846057Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27
[INFO] [stdout] 2025-10-01T17:40:44.846071Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27
[INFO] [stdout] 2025-10-01T17:40:44.846097Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26
[INFO] [stdout] 2025-10-01T17:40:44.846110Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38
[INFO] [stdout] 2025-10-01T17:40:44.846123Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23
[INFO] [stdout] 2025-10-01T17:40:44.846145Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23
[INFO] [stdout] 2025-10-01T17:40:44.846157Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26
[INFO] [stdout] 2025-10-01T17:40:44.846199Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 } clk=17 req.finish_time=37
[INFO] [stdout] 2025-10-01T17:40:44.846216Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.846238Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.846247Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.846257Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.846279Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.846287Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.846297Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.846318Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.846327Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.846338Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.846345Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.846367Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.846377Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.846385Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.846395Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.846415Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.846423Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.846432Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.846496Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.846506Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.846516Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.846525Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 
[INFO] [stdout] 2025-10-01T17:40:44.846557Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.842816Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.846566Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] test utils::tests::test_addr ... ok
[INFO] [stdout] 2025-10-01T17:40:44.846577Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.842772Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.846636Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.846653Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.846628Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.846675Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.846680Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.846687Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.846698Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.846726Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.846738Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.846767Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.846695Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.846799Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.846811Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.846809Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.846824Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.846778Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.846854Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.846866Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.846890Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.846908Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.846932Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.846949Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.846973Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.846987Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.847009Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.847027Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.847049Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.847063Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.847088Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847097Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847120Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.847130Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.847142Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.847162Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.847179Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847188Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847209Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847219Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847240Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847249Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.847271Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.847281Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847291Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.847310Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.847319Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.847343Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.847353Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847372Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847382Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847404Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847416Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847436Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847467Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847488Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847499Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847509Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847520Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847539Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847548Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847568Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847578Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847597Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847607Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847618Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847641Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847653Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847666Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847694Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847707Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847728Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847740Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847753Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847775Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847788Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847809Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.847820Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2025-10-01T17:40:44.847967Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.847989Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.848003Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=0
[INFO] [stdout] 2025-10-01T17:40:44.848014Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.848037Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.848051Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.848075Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.848088Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.848116Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=0
[INFO] [stdout] 2025-10-01T17:40:44.848129Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=39
[INFO] [stdout] 2025-10-01T17:40:44.848141Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=55
[INFO] [stdout] 2025-10-01T17:40:44.848163Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=1
[INFO] [stdout] 2025-10-01T17:40:44.848184Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=0
[INFO] [stdout] 2025-10-01T17:40:44.848211Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=16
[INFO] [stdout] 2025-10-01T17:40:44.848226Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=16
[INFO] [stdout] 2025-10-01T17:40:44.848252Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=16
[INFO] [stdout] 2025-10-01T17:40:44.848264Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=16
[INFO] [stdout] 2025-10-01T17:40:44.848286Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=55
[INFO] [stdout] 2025-10-01T17:40:44.848300Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=39
[INFO] [stdout] 2025-10-01T17:40:44.848325Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.848334Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.848343Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.848353Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.848371Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.848380Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.848403Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.848410Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.848419Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.848452Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.848462Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.848471Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.848482Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.848504Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.848513Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.848535Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.848543Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.848565Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.848574Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.848582Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.848591Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.848611Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.848619Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.848628Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.848652Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.848660Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.848668Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.848690Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.848698Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.848707Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.848716Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.848735Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.848745Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.848763Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.848797Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.848807Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.848828Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.848837Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.848847Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.848869Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.848878Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.848888Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.848910Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.848917Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.848927Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.848945Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.848952Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.848961Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.848982Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=16
[INFO] [stdout] 2025-10-01T17:40:44.848993Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.849016Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.849029Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.849053Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.849064Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=20
[INFO] [stdout] 2025-10-01T17:40:44.849087Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=20
[INFO] [stdout] 2025-10-01T17:40:44.849100Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=20
[INFO] [stdout] 2025-10-01T17:40:44.849121Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=20
[INFO] [stdout] 2025-10-01T17:40:44.849134Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=26
[INFO] [stdout] 2025-10-01T17:40:44.849161Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=26
[INFO] [stdout] 2025-10-01T17:40:44.849191Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=39 future=25
[INFO] [stdout] 2025-10-01T17:40:44.849207Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=1 future=37
[INFO] [stdout] 2025-10-01T17:40:44.849231Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=22
[INFO] [stdout] 2025-10-01T17:40:44.849246Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=22
[INFO] [stdout] 2025-10-01T17:40:44.849269Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=39 future=25
[INFO] [stdout] 2025-10-01T17:40:44.849287Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 36 } clk=16 req.finish_time=36
[INFO] [stdout] 2025-10-01T17:40:44.842097Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2025-10-01T17:40:44.849504Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2025-10-01T17:40:44.849541Z  INFO ramu_rs::ddr4: speed_entry speed_entry=SpeedEntry { rate: 2400, freq: 1200.0, tCK: 0.8333333333333334, nBL: 4, nCCDS: 4, nCCDL: 6, nRTRS: 2, nCL: 16, nRCD: 16, nRP: 16, nCWL: 12, nRAS: 39, nRC: 55, nRTP: 9, nWTRS: 3, nWTRL: 9, nWR: 18, nRRDS: 0, nRRDL: 0, nFAW: 0, nRFC: 0, nREFI: 0, nPD: 6, nXP: 8, nXPDLL: 0, nCKESR: 7, nXS: 0, nXSDLL: 0 }
[INFO] [stdout] 2025-10-01T17:40:44.846825Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.849624Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.849634Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.842736Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.849608Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.849667Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.849677Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.849695Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.849704Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.849710Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.849715Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.849792Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.849823Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.849836Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.849852Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.849863Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.849882Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.849892Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.849902Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.849917Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.849928Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.849945Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.849970Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850001Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850015Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850036Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850046Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850056Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850071Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850089Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850101Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850117Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850126Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850143Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850153Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850168Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850181Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850193Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850215Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850227Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850248Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850260Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850273Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850296Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850308Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850319Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850332Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850353Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850366Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.850386Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850399Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850410Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850422Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850432Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850460Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850471Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850495Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850506Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850517Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850534Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850544Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850564Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850576Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850594Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850616Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850627Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850646Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850669Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850680Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850703Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850714Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850723Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850733Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850743Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850758Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850786Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850798Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850810Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.850829Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2025-10-01T17:40:44.851009Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192
[INFO] [stdout] 2025-10-01T17:40:44.851040Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.851052Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.851069Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1
[INFO] [stdout] 2025-10-01T17:40:44.851090Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.851101Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.851116Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.851126Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.851143Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.851156Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-10-01T17:40:44.851170Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40
[INFO] [stdout] 2025-10-01T17:40:44.851184Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56
[INFO] [stdout] 2025-10-01T17:40:44.851203Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2
[INFO] [stdout] 2025-10-01T17:40:44.851221Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-10-01T17:40:44.851241Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17
[INFO] [stdout] 2025-10-01T17:40:44.851263Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17
[INFO] [stdout] 2025-10-01T17:40:44.851276Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17
[INFO] [stdout] 2025-10-01T17:40:44.851289Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17
[INFO] [stdout] 2025-10-01T17:40:44.851303Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56
[INFO] [stdout] 2025-10-01T17:40:44.851321Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40
[INFO] [stdout] 2025-10-01T17:40:44.851338Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.851352Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.851361Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.851378Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.851386Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.851394Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.851404Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.851414Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.851422Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.851452Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.851462Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.851472Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.851481Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.851491Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.851500Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.851515Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.851522Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.851536Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.851546Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.851559Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.851568Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.851577Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.851585Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.851594Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.851605Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.851612Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.851628Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.851637Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.851650Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.851658Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.851667Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.851683Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.851696Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.851705Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.851713Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.851723Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.851732Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.851747Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.851755Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.851769Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.851776Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.851785Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.851804Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.851812Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.851821Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.851834Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.851842Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.851856Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.851866Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.851873Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.851886Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.851895Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.851912Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.851920Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.851929Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.851937Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.851948Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.851957Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.851964Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.851973Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.851988Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.852001Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.852009Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.852023Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.852030Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.852045Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.852054Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.852062Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.852070Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.852079Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.852091Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.852100Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.852117Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.852126Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.852141Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.852151Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.852170Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.852179Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.852189Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.852198Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.852211Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.852222Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.852239Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.852251Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.852260Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.852275Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.852289Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.852301Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.852308Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.852321Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.852335Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.852347Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.852363Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.852375Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17
[INFO] [stdout] 2025-10-01T17:40:44.852384Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.852400Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.852413Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.852424Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.852437Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21
[INFO] [stdout] 2025-10-01T17:40:44.854503Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21
[INFO] [stdout] 2025-10-01T17:40:44.854521Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21
[INFO] [stdout] 2025-10-01T17:40:44.854534Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21
[INFO] [stdout] 2025-10-01T17:40:44.854548Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27
[INFO] [stdout] 2025-10-01T17:40:44.854569Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27
[INFO] [stdout] 2025-10-01T17:40:44.854582Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26
[INFO] [stdout] 2025-10-01T17:40:44.854599Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38
[INFO] [stdout] 2025-10-01T17:40:44.854612Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23
[INFO] [stdout] 2025-10-01T17:40:44.854630Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23
[INFO] [stdout] 2025-10-01T17:40:44.854646Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26
[INFO] [stdout] 2025-10-01T17:40:44.854665Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 } clk=17 req.finish_time=37
[INFO] [stdout] 2025-10-01T17:40:44.854692Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.854701Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.854710Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.854727Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.854735Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.854745Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.854756Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.854764Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.854773Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.854792Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.854801Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.854811Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.854828Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.854837Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.854846Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.854860Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.854868Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.854877Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.854887Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.854895Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.854905Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.854914Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.854930Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.854938Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.854948Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.854958Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.854968Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.854978Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.854993Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.855003Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.855013Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855026Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.855036Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.855053Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855061Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.855076Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.855086Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855095Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.855105Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.855118Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855127Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.855136Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.855146Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855155Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.855170Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.855180Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855187Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.855202Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.855212Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855220Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.855230Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.855239Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855247Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.855259Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.855269Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855284Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.855294Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.855312Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855320Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.855336Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.855359Z DEBUG ramu_rs::test: recv req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 }
[INFO] [stdout] 2025-10-01T17:40:44.855376Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855385Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.855401Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.855411Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855427Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.855436Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.855526Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855537Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.855547Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.855557Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40
[INFO] [stdout] 2025-10-01T17:40:44.855566Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.855579Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.855599Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.855610Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-01T17:40:44.855629Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56
[INFO] [stdout] 2025-10-01T17:40:44.855643Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56
[INFO] [stdout] 2025-10-01T17:40:44.855674Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56
[INFO] [stdout] 2025-10-01T17:40:44.855692Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855701Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.855713Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855731Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.855742Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855757Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.855768Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855777Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.855798Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855808Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.855819Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855827Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.855850Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855859Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.855875Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855884Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.855896Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855905Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.855916Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855931Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.855942Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855950Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.855968Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.855978Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.856001Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856009Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.856019Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856030Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.856041Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856050Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.856060Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856077Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.856090Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56
[INFO] [stdout] 2025-10-01T17:40:44.856107Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.856120Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.856132Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.856143Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-01T17:40:44.856162Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.856173Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56
[INFO] [stdout] 2025-10-01T17:40:44.856195Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95
[INFO] [stdout] 2025-10-01T17:40:44.856209Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111
[INFO] [stdout] 2025-10-01T17:40:44.856226Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57
[INFO] [stdout] 2025-10-01T17:40:44.856241Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56
[INFO] [stdout] 2025-10-01T17:40:44.856257Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72
[INFO] [stdout] 2025-10-01T17:40:44.856278Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72
[INFO] [stdout] 2025-10-01T17:40:44.856300Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72
[INFO] [stdout] 2025-10-01T17:40:44.856320Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72
[INFO] [stdout] 2025-10-01T17:40:44.856334Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111
[INFO] [stdout] 2025-10-01T17:40:44.856348Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95
[INFO] [stdout] 2025-10-01T17:40:44.856365Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856384Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.856405Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.856428Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856437Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.856464Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.856475Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856484Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.856494Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.856505Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856514Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.856523Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.856542Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856552Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.856569Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.856581Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856590Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.856600Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.856610Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856619Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.856637Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.856649Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856664Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.856673Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.856684Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856693Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.856702Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.856716Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856724Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.856740Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.856752Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856761Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.856778Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.856789Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856798Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.856808Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.856821Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856829Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.856847Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.856858Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856875Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.856886Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.856897Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856905Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.856914Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.856935Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.856944Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.856954Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.856970Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=72
[INFO] [stdout] 2025-10-01T17:40:44.856987Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.856999Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.857022Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.857034Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-01T17:40:44.857047Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=76
[INFO] [stdout] 2025-10-01T17:40:44.857062Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=76
[INFO] [stdout] 2025-10-01T17:40:44.857084Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=27 future=76
[INFO] [stdout] 2025-10-01T17:40:44.857103Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=27 future=76
[INFO] [stdout] 2025-10-01T17:40:44.857118Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=21 future=91
[INFO] [stdout] 2025-10-01T17:40:44.857132Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=21 future=91
[INFO] [stdout] 2025-10-01T17:40:44.857155Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=95 future=106
[INFO] [stdout] 2025-10-01T17:40:44.857168Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=57 future=106
[INFO] [stdout] 2025-10-01T17:40:44.857182Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=78
[INFO] [stdout] 2025-10-01T17:40:44.857194Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=78
[INFO] [stdout] 2025-10-01T17:40:44.857212Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=23 future=97
[INFO] [stdout] 2025-10-01T17:40:44.857225Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=23 future=97
[INFO] [stdout] 2025-10-01T17:40:44.857244Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=95 future=106
[INFO] [stdout] 2025-10-01T17:40:44.857265Z DEBUG ramu_rs::controller: write request finished req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 72 }
[INFO] [stdout] 2025-10-01T17:40:44.857283Z DEBUG ramu_rs::test: recv req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 72 }
[INFO] [stdout] 2025-10-01T17:40:44.849667Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.849731Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.857643Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.857668Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.857682Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.857683Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.857699Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.857713Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.857712Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.857760Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.857782Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.857804Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.857816Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.857834Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.857843Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.857854Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.857863Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.857874Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.857886Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.857901Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.857911Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.857929Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.857938Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.857948Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.857958Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.857965Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.857974Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.857996Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858006Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.858023Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.858035Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858049Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.858059Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.858073Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858081Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.858108Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.858128Z DEBUG ramu_rs::test: recv req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 37 }
[INFO] [stdout] 2025-10-01T17:40:44.858148Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858158Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.858167Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.858177Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858187Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.858196Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.858214Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858222Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.858240Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.858252Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40
[INFO] [stdout] 2025-10-01T17:40:44.858267Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.858279Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.858297Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.858308Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-01T17:40:44.858323Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56
[INFO] [stdout] 2025-10-01T17:40:44.858338Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56
[INFO] [stdout] 2025-10-01T17:40:44.858365Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56
[INFO] [stdout] 2025-10-01T17:40:44.858389Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858407Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.858418Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858427Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.858457Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858475Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.858486Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858500Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.858510Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858518Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.858530Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858537Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.858547Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858555Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.858564Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858582Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.858594Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858608Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.858619Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858628Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.858639Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858652Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.858663Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858671Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.858684Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858692Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.858712Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858721Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.858738Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858746Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.858763Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.858771Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.858781Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56
[INFO] [stdout] 2025-10-01T17:40:44.858791Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.858804Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.858823Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.858844Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-01T17:40:44.858856Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.858874Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56
[INFO] [stdout] 2025-10-01T17:40:44.858889Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95
[INFO] [stdout] 2025-10-01T17:40:44.858903Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111
[INFO] [stdout] 2025-10-01T17:40:44.858920Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57
[INFO] [stdout] 2025-10-01T17:40:44.858941Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56
[INFO] [stdout] 2025-10-01T17:40:44.858963Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72
[INFO] [stdout] 2025-10-01T17:40:44.858994Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72
[INFO] [stdout] 2025-10-01T17:40:44.859010Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72
[INFO] [stdout] 2025-10-01T17:40:44.859024Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72
[INFO] [stdout] 2025-10-01T17:40:44.859039Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111
[INFO] [stdout] 2025-10-01T17:40:44.859064Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95
[INFO] [stdout] 2025-10-01T17:40:44.859089Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.859107Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.859117Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.859128Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.859137Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.859155Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.859167Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.859183Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.859193Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.859204Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.859212Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.859221Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.859232Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.859250Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.859260Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.859279Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.859288Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.859298Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.859309Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.859321Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.859332Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.859342Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.859351Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.859370Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.859382Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.859397Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.859407Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.859418Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.859427Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.859471Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.859541Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859561Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859575Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859586Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859615Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859632Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859653Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859676Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859688Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859699Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859722Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859734Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859748Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859760Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.859770Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.859791Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859803Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859821Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859834Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859847Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.859862Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.859872Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.859889Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.859901Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.859919Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859945Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859957Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.859970Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.859987Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.860001Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.860011Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.860025Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860036Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860052Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860061Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860078Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860089Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860101Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860114Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860124Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860142Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860153Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860163Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860179Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860189Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860198Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860209Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860222Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860243Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860255Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860271Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860281Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860295Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860307Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860317Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860331Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860342Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860354Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860364Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860381Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.860393Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2025-10-01T17:40:44.860630Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=1
[INFO] [stdout] 2025-10-01T17:40:44.860696Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 0]
[INFO] [stdout] 2025-10-01T17:40:44.860738Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 0
[INFO] [stdout] 2025-10-01T17:40:44.860765Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=65
[INFO] [stdout] 2025-10-01T17:40:44.860794Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 1]
[INFO] [stdout] 2025-10-01T17:40:44.860815Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 64
[INFO] [stdout] 2025-10-01T17:40:44.860839Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=257
[INFO] [stdout] 2025-10-01T17:40:44.860858Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 4]
[INFO] [stdout] 2025-10-01T17:40:44.860886Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 256
[INFO] [stdout] 2025-10-01T17:40:44.859500Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861046Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861065Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861079Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861091Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: ACT, dist: 4, val: 0, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 39, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861115Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PRE timing_command=[TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861128Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PREA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861147Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 9, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861168Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PREA, dist: 1, val: 34, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861185Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: true }, TimeEntry { cmd: WR, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: WRA, dist: 1, val: 10, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 21, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861203Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 4, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 19, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: RDA, dist: 1, val: 2, sibling: true }, TimeEntry { cmd: PDE, dist: 1, val: 35, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861227Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=REF timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 1, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861241Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861260Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDX timing_command=[TimeEntry { cmd: RD, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PREA, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 8, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 8, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861277Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861300Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRX timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: REF, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: PDE, dist: 1, val: 0, sibling: false }, TimeEntry { cmd: SRE, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861315Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861328Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861340Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861360Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RD timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861374Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WR timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861395Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=RDA timing_command=[TimeEntry { cmd: RD, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861409Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=WRA timing_command=[TimeEntry { cmd: WR, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 6, sibling: false }, TimeEntry { cmd: RD, dist: 1, val: 25, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861433Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861463Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861479Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861490Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861509Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861521Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=ACT timing_command=[TimeEntry { cmd: RD, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: RDA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WR, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: WRA, dist: 1, val: 16, sibling: false }, TimeEntry { cmd: ACT, dist: 1, val: 55, sibling: false }, TimeEntry { cmd: PRE, dist: 1, val: 39, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861543Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861556Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861567Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861580Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861595Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861617Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-10-01T17:40:44.861629Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861649Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861661Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861673Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861684Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861707Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861720Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861738Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861750Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861761Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861776Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861788Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861800Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861814Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861834Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861847Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861865Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861877Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861889Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861900Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861912Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861930Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861941Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861959Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861971Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.861989Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.862011Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.862024Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.862035Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2025-10-01T17:40:44.862048Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2025-10-01T17:40:44.862213Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192
[INFO] [stdout] 2025-10-01T17:40:44.862244Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.862255Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.862268Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1
[INFO] [stdout] 2025-10-01T17:40:44.862281Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.862306Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.862318Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.862336Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.862348Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.862359Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-10-01T17:40:44.862374Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40
[INFO] [stdout] 2025-10-01T17:40:44.862395Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56
[INFO] [stdout] 2025-10-01T17:40:44.862410Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2
[INFO] [stderr] error: test failed, to rerun pass `--lib`
[INFO] [stdout] 2025-10-01T17:40:44.862430Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-10-01T17:40:44.862464Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17
[INFO] [stdout] 2025-10-01T17:40:44.862483Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17
[INFO] [stdout] 2025-10-01T17:40:44.862497Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17
[INFO] [stdout] 2025-10-01T17:40:44.862529Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17
[INFO] [stdout] 2025-10-01T17:40:44.862551Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56
[INFO] [stdout] 2025-10-01T17:40:44.862565Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40
[INFO] [stdout] 2025-10-01T17:40:44.862589Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.862604Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.862614Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.862632Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.862642Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.862652Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.862667Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.862676Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.862686Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.862697Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.862706Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.862717Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.862727Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.862736Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.862753Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.862764Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.862777Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.862787Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.862806Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.862815Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.862831Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.862843Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.862853Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.862864Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.862875Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.862892Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.862903Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.862921Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.862930Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.862940Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.862952Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.862960Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.862977Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.863004Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863013Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.863023Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.863034Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863043Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.863053Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.863071Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863080Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.863096Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.863108Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863118Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.863131Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.863141Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863150Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.863160Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.863182Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863191Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.863207Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.863219Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863227Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.863237Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.863253Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863262Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.863271Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.863281Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863290Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.863311Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.863322Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863331Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.863347Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.863358Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863368Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.863381Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.863391Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863400Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.863409Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.863429Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863453Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.863465Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.863478Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863497Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.863509Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.863526Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863536Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.863546Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.863560Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863569Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.863580Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.863590Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863598Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.863617Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.863630Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863646Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.863657Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.863668Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863677Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.863689Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.863701Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.863709Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-10-01T17:40:44.863720Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.863731Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=17
[INFO] [stdout] 2025-10-01T17:40:44.863749Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.863761Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.863780Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.863793Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.863806Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=21
[INFO] [stdout] 2025-10-01T17:40:44.863821Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=21
[INFO] [stdout] 2025-10-01T17:40:44.863837Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=0 future=21
[INFO] [stdout] 2025-10-01T17:40:44.863859Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=0 future=21
[INFO] [stdout] 2025-10-01T17:40:44.863880Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=0 future=36
[INFO] [stdout] 2025-10-01T17:40:44.863895Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=0 future=36
[INFO] [stdout] 2025-10-01T17:40:44.863916Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=40 future=51
[INFO] [stdout] 2025-10-01T17:40:44.863930Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=2 future=51
[INFO] [stdout] 2025-10-01T17:40:44.863949Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=23
[INFO] [stdout] 2025-10-01T17:40:44.863970Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=23
[INFO] [stdout] 2025-10-01T17:40:44.863994Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=0 future=42
[INFO] [stdout] 2025-10-01T17:40:44.864009Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=0 future=42
[INFO] [stdout] 2025-10-01T17:40:44.864079Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.864123Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.864134Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.864145Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.864156Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.864164Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.864176Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.864186Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.864195Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.864205Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.864216Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.864225Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.864236Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.864247Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.864256Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.864266Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.864277Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-10-01T17:40:44.864286Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.864296Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-10-01T17:40:44.864308Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=72
[INFO] [stdout] 2025-10-01T17:40:44.864319Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.864331Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.864343Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.864356Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-01T17:40:44.864369Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=21 future=76
[INFO] [stdout] 2025-10-01T17:40:44.864383Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=21 future=76
[INFO] [stdout] 2025-10-01T17:40:44.864402Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=21 future=76
[INFO] [stdout] 2025-10-01T17:40:44.864417Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=21 future=76
[INFO] [stdout] 2025-10-01T17:40:44.864431Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=27 future=82
[INFO] [stdout] 2025-10-01T17:40:44.864464Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=27 future=82
[INFO] [stdout] 2025-10-01T17:40:44.864479Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=95 future=81
[INFO] [stdout] 2025-10-01T17:40:44.864494Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=57 future=93
[INFO] [stdout] 2025-10-01T17:40:44.864510Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=23 future=78
[INFO] [stdout] 2025-10-01T17:40:44.864525Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=23 future=78
[INFO] [stdout] 2025-10-01T17:40:44.864541Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=95 future=81
[INFO] [stdout] 2025-10-01T17:40:44.864558Z DEBUG ramu_rs::controller: read request finished req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 92 } clk=72 req.finish_time=92
[INFO] [stdout] 2025-10-01T17:40:44.864580Z 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_read_and_write ... ok
[INFO] [stdout] test ddr4::tests::test_address ... ok
[INFO] [stdout] test test::test_memory_diffrent_row ... ok
[INFO] [stdout] 2025-10-01T17:40:44.864923Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=40 future=51
[INFO] [stdout] 2025-10-01T17:40:44.864945Z DEBUG ramu_rs::controller: write request finished req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 17 }
[INFO] [stdout] 2025-10-01T17:40:44.864965Z DEBUG ramu_rs::test: recv req=Request { addr: 0, addr_vec: [0, 0, 0, 0, 0, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 17 }
[INFO] [stdout] 2025-10-01T17:40:44.864975Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.864995Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865005Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865017Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865024Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865033Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865044Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865051Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865061Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865070Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865078Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865086Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865095Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865102Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865110Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865118Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865126Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865135Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865145Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865153Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865162Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865173Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865181Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865190Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865199Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865207Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865215Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865225Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865233Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865242Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865253Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865264Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865274Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865285Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865294Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865303Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865313Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865322Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865331Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865342Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865350Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865360Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865370Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865378Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865388Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865399Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865407Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865417Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865427Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865434Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865464Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865476Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865484Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865494Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865504Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865513Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865522Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865533Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865542Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865554Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865565Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865573Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865583Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865593Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865602Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865612Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865624Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865632Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865640Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865650Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865657Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865667Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865676Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865684Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865693Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865703Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865711Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865720Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865731Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865740Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865751Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865763Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865772Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865783Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865795Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865805Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865816Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865832Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865842Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865853Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865865Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865875Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865885Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865894Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865901Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865910Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865921Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865930Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865942Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865952Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.865961Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.865970Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-10-01T17:40:44.865994Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=51
[INFO] [stdout] 2025-10-01T17:40:44.866003Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.866014Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.866024Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.866034Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-01T17:40:44.866047Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=67
[INFO] [stdout] 2025-10-01T17:40:44.866060Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=67
[INFO] [stdout] 2025-10-01T17:40:44.866072Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=67
[INFO] [stdout] 2025-10-01T17:40:44.866087Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866097Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.866108Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866117Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.866127Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866135Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.866145Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866153Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.866163Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866171Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.866182Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866190Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.866200Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866208Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.866218Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866226Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.866236Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866244Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.866254Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866263Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.866273Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866281Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.866291Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866299Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.866309Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866317Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.866327Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866335Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.866345Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866356Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.866366Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866374Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-10-01T17:40:44.866385Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=67
[INFO] [stdout] 2025-10-01T17:40:44.866394Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.866405Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.866415Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.866425Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-01T17:40:44.866436Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.866540Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=67
[INFO] [stdout] 2025-10-01T17:40:44.866554Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=51 future=106
[INFO] [stdout] 2025-10-01T17:40:44.866567Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=67 future=122
[INFO] [stdout] 2025-10-01T17:40:44.866579Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=51 future=68
[INFO] [stdout] 2025-10-01T17:40:44.866592Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=67
[INFO] [stdout] 2025-10-01T17:40:44.866606Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=83
[INFO] [stdout] 2025-10-01T17:40:44.866618Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=83
[INFO] [stdout] 2025-10-01T17:40:44.866631Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=83
[INFO] [stdout] 2025-10-01T17:40:44.866643Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=83
[INFO] [stdout] 2025-10-01T17:40:44.866655Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=67 future=122
[INFO] [stdout] 2025-10-01T17:40:44.866668Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=51 future=106
[INFO] [stdout] 2025-10-01T17:40:44.866682Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866690Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.866702Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.866714Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866721Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.866730Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.866739Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866747Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.866756Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.866766Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866776Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.866785Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.866795Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866804Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.866813Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.866822Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866829Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.866837Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.866846Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866854Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.866863Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.866873Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866882Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.866892Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.866902Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866910Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.866920Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.866930Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866938Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.866948Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.866958Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.866966Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.866975Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.866992Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.867000Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.867008Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.867017Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.867025Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.867036Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.867046Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.867054Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.867062Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.867072Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.867080Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.867088Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.867097Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-10-01T17:40:44.867106Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-10-01T17:40:44.867115Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-10-01T17:40:44.867125Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=83
[INFO] [stdout] 2025-10-01T17:40:44.867135Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.867147Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.867158Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-10-01T17:40:44.867168Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-10-01T17:40:44.867181Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=21 future=87
[INFO] [stdout] 2025-10-01T17:40:44.867192Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=21 future=87
[INFO] [stdout] 2025-10-01T17:40:44.867203Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=21 future=87
[INFO] [stdout] 2025-10-01T17:40:44.867214Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=21 future=87
[INFO] [stdout] 2025-10-01T17:40:44.867224Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=36 future=102
[INFO] [stdout] 2025-10-01T17:40:44.867236Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=36 future=102
[INFO] [stdout] 2025-10-01T17:40:44.867249Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=106 future=117
[INFO] [stdout] 2025-10-01T17:40:44.867265Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=68 future=117
[INFO] [stdout] 2025-10-01T17:40:44.867279Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=23 future=89
[INFO] [stdout] 2025-10-01T17:40:44.867293Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=23 future=89
[INFO] [stdout] 2025-10-01T17:40:44.867307Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=42 future=108
[INFO] [stdout] 2025-10-01T17:40:44.867320Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=42 future=108
[INFO] [stdout] 2025-10-01T17:40:44.867334Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=106 future=117
[INFO] [stdout] 2025-10-01T17:40:44.867348Z DEBUG ramu_rs::controller: write request finished req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 83 }
[INFO] [stdout] 2025-10-01T17:40:44.867359Z DEBUG ramu_rs::test: recv req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 83 }
[INFO] [stdout] test test::test_memory_write ... ok
[INFO] [stdout] test 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' (24) panicked at src/controller.rs:300:9:
[INFO] [stdout] assertion failed: controller.finished_queue.is_empty()
[INFO] [stdout] stack backtrace:
[INFO] [stdout]    0:     0x59fffa89ecb2 - std::backtrace_rs::backtrace::libunwind::trace::h22a6a535a50603c6
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/../../backtrace/src/backtrace/libunwind.rs:117:9
[INFO] [stdout]    1:     0x59fffa89ecb2 - std::backtrace_rs::backtrace::trace_unsynchronized::h2503a4f30dbfbaa2
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/../../backtrace/src/backtrace/mod.rs:66:14
[INFO] [stdout]    2:     0x59fffa89ecb2 - std::sys::backtrace::_print_fmt::hec54e31f36456895
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/sys/backtrace.rs:66:9
[INFO] [stdout]    3:     0x59fffa89ecb2 - <std::sys::backtrace::BacktraceLock::print::DisplayBacktrace as core::fmt::Display>::fmt::hb1988e8b50fa5f19
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/sys/backtrace.rs:39:26
[INFO] [stdout]    4:     0x59fffa8b017f - core::fmt::rt::Argument::fmt::h3118a66e1a57a586
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/core/src/fmt/rt.rs:173:76
[INFO] [stdout]    5:     0x59fffa8b017f - core::fmt::write::hcd056e06a609f600
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/core/src/fmt/mod.rs:1468:25
[INFO] [stdout]    6:     0x59fffa86b801 - std::io::default_write_fmt::hdabc5d6505cb374b
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/io/mod.rs:639:11
[INFO] [stdout]    7:     0x59fffa86b801 - std::io::Write::write_fmt::h18c82179fdc1f9d2
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/io/mod.rs:1954:13
[INFO] [stdout]    8:     0x59fffa877b72 - std::sys::backtrace::BacktraceLock::print::h69f50ba7cfff8317
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/sys/backtrace.rs:42:9
[INFO] [stdout]    9:     0x59fffa87c86f - std::panicking::default_hook::{{closure}}::hfa978eb2255ab3ab
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/panicking.rs:301:27
[INFO] [stdout]   10:     0x59fffa87c701 - std::panicking::default_hook::h09da2eaf8f1deadd
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/panicking.rs:325:9
[INFO] [stdout]   11:     0x59fffa69044e - <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call::h1697e4d80f236ef6
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/alloc/src/boxed.rs:1987:9
[INFO] [stdout]   12:     0x59fffa69044e - test::test_main_with_exit_callback::{{closure}}::h8f63929ca9fd483b
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/test/src/lib.rs:145:21
[INFO] [stdout]   13:     0x59fffa87cf2f - <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call::hba67e0dc3e3fc548
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/alloc/src/boxed.rs:1987:9
[INFO] [stdout]   14:     0x59fffa87cf2f - std::panicking::panic_with_hook::h13c40d280d130fd3
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/panicking.rs:842:13
[INFO] [stdout]   15:     0x59fffa87cd56 - std::panicking::panic_handler::{{closure}}::hd79d22e8a1d3b951
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/panicking.rs:700:13
[INFO] [stdout]   16:     0x59fffa877cb9 - std::sys::backtrace::__rust_end_short_backtrace::h83414d1ec69cf3a6
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/sys/backtrace.rs:174:18
[INFO] [stdout]   17:     0x59fffa85ff9d - __rustc[b78aa6c7b08e5dc4]::rust_begin_unwind
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/panicking.rs:698:5
[INFO] [stdout]   18:     0x59fffa8b9900 - core::panicking::panic_fmt::h326b75cf8ee01b13
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/core/src/panicking.rs:78:14
[INFO] [stdout]   19:     0x59fffa8b98dc - core::panicking::panic::h9eb31005fec5715e
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/core/src/panicking.rs:148:5
[INFO] [stdout]   20:     0x59fffa652adf - ramu_rs::controller::tests::test_controller_simple_read::hb26b70699fe5b333
[INFO] [stdout]                                at /opt/rustwide/workdir/src/controller.rs:300:9
[INFO] [stdout]   21:     0x59fffa652be7 - ramu_rs::controller::tests::test_controller_simple_read::{{closure}}::h251bebdd9b516566
[INFO] [stdout]                                at /opt/rustwide/workdir/src/controller.rs:277:37
[INFO] [stdout]   22:     0x59fffa663056 - core::ops::function::FnOnce::call_once::ha80250e89f7940c9
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/core/src/ops/function.rs:250:5
[INFO] [stdout]   23:     0x59fffa69022b - core::ops::function::FnOnce::call_once::he420dad47d9aac14
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/core/src/ops/function.rs:250:5
[INFO] [stdout]   24:     0x59fffa69022b - test::__rust_begin_short_backtrace::h51976f55c263f7c2
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/test/src/lib.rs:663:18
[INFO] [stdout]   25:     0x59fffa6a5e55 - test::run_test_in_process::{{closure}}::h6aa4339396d33320
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/test/src/lib.rs:686:74
[INFO] [stdout]   26:     0x59fffa6a5e55 - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h5bd0ba3863a53529
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/core/src/panic/unwind_safe.rs:274:9
[INFO] [stdout]   27:     0x59fffa6a5e55 - std::panicking::catch_unwind::do_call::h5c710722c40c5839
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/panicking.rs:590:40
[INFO] [stdout]   28:     0x59fffa6a5e55 - std::panicking::catch_unwind::hf41b5be070ce0f19
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/panicking.rs:553:19
[INFO] [stdout]   29:     0x59fffa6a5e55 - std::panic::catch_unwind::h4559aa103e6f16d6
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/panic.rs:359:14
[INFO] [stdout]   30:     0x59fffa6a5e55 - test::run_test_in_process::he6fd763a772ff213
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/test/src/lib.rs:686:27
[INFO] [stdout]   31:     0x59fffa6a5e55 - test::run_test::{{closure}}::he46f5435849feb5b
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/test/src/lib.rs:607:43
[INFO] [stdout]   32:     0x59fffa67c664 - test::run_test::{{closure}}::h12a66289c31b502a
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/test/src/lib.rs:637:41
[INFO] [stdout]   33:     0x59fffa67c664 - std::sys::backtrace::__rust_begin_short_backtrace::h614a7925ed7b2f5e
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/sys/backtrace.rs:158:18
[INFO] [stdout]   34:     0x59fffa68000a - std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}::hbc654088c5dbff36
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/thread/mod.rs:559:17
[INFO] [stdout]   35:     0x59fffa68000a - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h3f631d2ca531b61d
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/core/src/panic/unwind_safe.rs:274:9
[INFO] [stdout]   36:     0x59fffa68000a - std::panicking::catch_unwind::do_call::hd2548748db0aa717
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/panicking.rs:590:40
[INFO] [stdout]   37:     0x59fffa68000a - std::panicking::catch_unwind::hf7d8620d84df48e2
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/panicking.rs:553:19
[INFO] [stdout]   38:     0x59fffa68000a - std::panic::catch_unwind::hdde75b8543fcb96b
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/panic.rs:359:14
[INFO] [stdout]   39:     0x59fffa68000a - std::thread::Builder::spawn_unchecked_::{{closure}}::h991e7d03b432cf3f
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/thread/mod.rs:557:30
[INFO] [stdout]   40:     0x59fffa68000a - core::ops::function::FnOnce::call_once{{vtable.shim}}::hebddb40255441657
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/core/src/ops/function.rs:250:5
[INFO] [stdout]   41:     0x59fffa872def - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h55e8930dc7db99a5
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/alloc/src/boxed.rs:1973:9
[INFO] [stdout]   42:     0x59fffa872def - std::sys::thread::unix::Thread::new::thread_start::he23d038ee4fa004e
[INFO] [stdout]                                at /rustc/2440211fe03bc45c89b6dc1a3df18382ce91e32b/library/std/src/sys/thread/unix.rs:126:17
[INFO] [stdout]   43:     0x71a8a2071aa4 - <unknown>
[INFO] [stdout]   44:     0x71a8a20fea34 - 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.05s
[INFO] [stdout] 
[INFO] running `Command { std: "docker" "inspect" "3a8c5057b42020320c8039603addce30a9f3e6d92a548418ff1627e983b23e74", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "3a8c5057b42020320c8039603addce30a9f3e6d92a548418ff1627e983b23e74", kill_on_drop: false }`
[INFO] [stdout] 3a8c5057b42020320c8039603addce30a9f3e6d92a548418ff1627e983b23e74