[INFO] fetching crate ramu_rs 0.1.1...
[INFO] testing ramu_rs-0.1.1 against beta-2025-10-28 for beta-1.92-2
[INFO] extracting crate ramu_rs 0.1.1 into /workspace/builds/worker-5-tc2/source
[INFO] started tweaking crates.io crate ramu_rs 0.1.1
[INFO] finished tweaking crates.io crate ramu_rs 0.1.1
[INFO] tweaked toml for crates.io crate ramu_rs 0.1.1 written to /workspace/builds/worker-5-tc2/source/Cargo.toml
[INFO] validating manifest of crates.io crate ramu_rs 0.1.1 on toolchain beta-2025-10-28
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+beta-2025-10-28" "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" "+beta-2025-10-28" "generate-lockfile" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Updating crates.io index
[INFO] [stderr]     Blocking waiting for file lock on package cache
[INFO] [stderr]      Locking 62 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.5)
[INFO] [stderr]       Adding toml v0.5.11 (available: v0.9.8)
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+beta-2025-10-28" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]     Blocking waiting for file lock on package cache
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2025-10-28" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] dde1f67f281b4158a9b2ba7de34a7d45f4297057151ed44e6274b6bfac22d35d
[INFO] running `Command { std: "docker" "start" "-a" "dde1f67f281b4158a9b2ba7de34a7d45f4297057151ed44e6274b6bfac22d35d", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "dde1f67f281b4158a9b2ba7de34a7d45f4297057151ed44e6274b6bfac22d35d", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "dde1f67f281b4158a9b2ba7de34a7d45f4297057151ed44e6274b6bfac22d35d", kill_on_drop: false }`
[INFO] [stdout] dde1f67f281b4158a9b2ba7de34a7d45f4297057151ed44e6274b6bfac22d35d
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2025-10-28" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] eb223354407f333ed476bb5ee926c555e10778e38407b623481848f2c9513694
[INFO] running `Command { std: "docker" "start" "-a" "eb223354407f333ed476bb5ee926c555e10778e38407b623481848f2c9513694", kill_on_drop: false }`
[INFO] [stderr]    Compiling hashbrown v0.16.0
[INFO] [stderr]    Compiling equivalent v1.0.2
[INFO] [stderr]    Compiling syn v1.0.109
[INFO] [stderr]    Compiling toml_datetime v0.6.11
[INFO] [stderr]    Compiling winnow v0.5.40
[INFO] [stderr]    Compiling cxxbridge-flags v1.0.187
[INFO] [stderr]    Compiling tracing-core v0.1.34
[INFO] [stderr]    Compiling regex-automata v0.4.13
[INFO] [stderr]    Compiling link-cplusplus v1.0.12
[INFO] [stderr]    Compiling thread_local v1.1.9
[INFO] [stderr]    Compiling sharded-slab v0.1.7
[INFO] [stderr]    Compiling nu-ansi-term v0.50.3
[INFO] [stderr]    Compiling foldhash v0.2.0
[INFO] [stderr]    Compiling syn v2.0.108
[INFO] [stderr]    Compiling heck v0.4.1
[INFO] [stderr]    Compiling cxx v1.0.187
[INFO] [stderr]    Compiling indexmap v2.12.0
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling matchers v0.2.0
[INFO] [stderr]    Compiling toml_edit v0.19.15
[INFO] [stderr]    Compiling enum-as-inner v0.5.1
[INFO] [stderr]    Compiling tracing-attributes v0.1.30
[INFO] [stderr]    Compiling serde_derive v1.0.228
[INFO] [stderr]    Compiling cxxbridge-macro v1.0.187
[INFO] [stderr]    Compiling proc-macro-crate v1.3.1
[INFO] [stderr]    Compiling num_enum_derive v0.5.11
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling tracing-subscriber v0.3.20
[INFO] [stderr]    Compiling num_enum v0.5.11
[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 21.64s
[INFO] running `Command { std: "docker" "inspect" "eb223354407f333ed476bb5ee926c555e10778e38407b623481848f2c9513694", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "eb223354407f333ed476bb5ee926c555e10778e38407b623481848f2c9513694", kill_on_drop: false }`
[INFO] [stdout] eb223354407f333ed476bb5ee926c555e10778e38407b623481848f2c9513694
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2025-10-28" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] a6f549a1878cf448539c5ce3d9d4eeaeef18861f2f2034bdf5113d76b0a4b6d5
[INFO] running `Command { std: "docker" "start" "-a" "a6f549a1878cf448539c5ce3d9d4eeaeef18861f2f2034bdf5113d76b0a4b6d5", kill_on_drop: false }`
[INFO] [stderr]    Compiling ramu_rs v0.1.1 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 1.80s
[INFO] running `Command { std: "docker" "inspect" "a6f549a1878cf448539c5ce3d9d4eeaeef18861f2f2034bdf5113d76b0a4b6d5", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "a6f549a1878cf448539c5ce3d9d4eeaeef18861f2f2034bdf5113d76b0a4b6d5", kill_on_drop: false }`
[INFO] [stdout] a6f549a1878cf448539c5ce3d9d4eeaeef18861f2f2034bdf5113d76b0a4b6d5
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-5-tc2/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=warn" "-e" "RUSTDOCFLAGS=--cap-lints=warn" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:4848fb76d95f26979359cc7e45710b1dbc8f3acb7aeedee7c460d7702230f228" "/opt/rustwide/cargo-home/bin/cargo" "+beta-2025-10-28" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 408177e6587578748fe180a8275c75b8f8443be2e58c58019a4a08d4fdd313b5
[INFO] running `Command { std: "docker" "start" "-a" "408177e6587578748fe180a8275c75b8f8443be2e58c58019a4a08d4fdd313b5", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.08s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/ramu_rs-7b1eb275b5d28743)
[INFO] [stdout] 
[INFO] [stdout] running 8 tests
[INFO] [stdout] 2025-11-05T05:03:06.959203Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2025-11-05T05:03:06.959256Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2025-11-05T05:03:06.959291Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2025-11-05T05:03:06.959314Z  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-11-05T05:03:06.959371Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.959394Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.959405Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.959415Z  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-11-05T05:03:06.959438Z  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-11-05T05:03:06.959451Z  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-11-05T05:03:06.959487Z  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-11-05T05:03:06.959501Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.959519Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.959530Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.959545Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.959556Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.959574Z  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-11-05T05:03:06.959597Z  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-11-05T05:03:06.959609Z  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-11-05T05:03:06.959621Z  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-11-05T05:03:06.959644Z  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-11-05T05:03:06.959659Z  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-11-05T05:03:06.959681Z  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-11-05T05:03:06.959695Z  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-11-05T05:03:06.959713Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.959725Z  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-11-05T05:03:06.959746Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.959758Z  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-11-05T05:03:06.959777Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.959789Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.959806Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.959817Z  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-11-05T05:03:06.959834Z  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-11-05T05:03:06.959847Z  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-11-05T05:03:06.959858Z  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] test config::tests::dum_config ... ignored
[INFO] [stdout] 2025-11-05T05:03:06.960759Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] test utils::tests::test_addr ... ok
[INFO] [stdout] test scheduler::tests::test ... ok
[INFO] [stdout] 2025-11-05T05:03:06.965820Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2025-11-05T05:03:06.962237Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2025-11-05T05:03:06.965522Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.965958Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2025-11-05T05:03:06.965990Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2025-11-05T05:03:06.966000Z  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-11-05T05:03:06.960717Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2025-11-05T05:03:06.966036Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.961667Z  INFO ramu_rs::ddr4: building ddr4
[INFO] [stdout] 2025-11-05T05:03:06.966049Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966061Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966054Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2025-11-05T05:03:06.966067Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128]
[INFO] [stdout] 2025-11-05T05:03:06.966070Z  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-11-05T05:03:06.966077Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2025-11-05T05:03:06.966084Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2025-11-05T05:03:06.966084Z  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-11-05T05:03:06.966088Z  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-11-05T05:03:06.966094Z  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-11-05T05:03:06.966095Z  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-11-05T05:03:06.966108Z  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-11-05T05:03:06.966120Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966118Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966124Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966130Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966131Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966136Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966140Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966145Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966147Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966150Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966155Z  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-11-05T05:03:06.966158Z  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-11-05T05:03:06.966160Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966168Z  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-11-05T05:03:06.966170Z  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-11-05T05:03:06.966171Z  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-11-05T05:03:06.966178Z  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-11-05T05:03:06.966182Z  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-11-05T05:03:06.966185Z  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-11-05T05:03:06.966188Z  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-11-05T05:03:06.966193Z  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-11-05T05:03:06.966196Z  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-11-05T05:03:06.966201Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966204Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966210Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966208Z  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-11-05T05:03:06.966219Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966223Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966229Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966225Z  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-11-05T05:03:06.966233Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966239Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966243Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966241Z  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-11-05T05:03:06.966249Z  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-11-05T05:03:06.966256Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966258Z  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-11-05T05:03:06.966262Z  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-11-05T05:03:06.966268Z  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-11-05T05:03:06.966271Z  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-11-05T05:03:06.966273Z  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-11-05T05:03:06.966281Z  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-11-05T05:03:06.966284Z  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-11-05T05:03:06.966305Z  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-11-05T05:03:06.966307Z  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-11-05T05:03:06.966317Z  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-11-05T05:03:06.966321Z  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-11-05T05:03:06.966334Z  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-11-05T05:03:06.966335Z  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-11-05T05:03:06.966350Z  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-11-05T05:03:06.966349Z  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-11-05T05:03:06.966362Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.966365Z  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-11-05T05:03:06.966373Z  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-11-05T05:03:06.966379Z  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-11-05T05:03:06.966390Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.966391Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.966400Z  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-11-05T05:03:06.966402Z  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-11-05T05:03:06.966411Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.966416Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.966421Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966428Z  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-11-05T05:03:06.966431Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966441Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.966441Z  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-11-05T05:03:06.966457Z  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-11-05T05:03:06.965910Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7]
[INFO] [stdout] 2025-11-05T05:03:06.966491Z  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-11-05T05:03:06.966500Z  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-11-05T05:03:06.966504Z  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-11-05T05:03:06.966516Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966527Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966530Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966537Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966540Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966547Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966549Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966557Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966559Z  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-11-05T05:03:06.966569Z  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-11-05T05:03:06.966567Z  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-11-05T05:03:06.966582Z  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-11-05T05:03:06.966584Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.966592Z  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-11-05T05:03:06.966595Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966602Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966604Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.966612Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966615Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.966621Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966626Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.966630Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966636Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.966640Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966648Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966649Z  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-11-05T05:03:06.966658Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966662Z  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-11-05T05:03:06.966668Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966672Z  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-11-05T05:03:06.966678Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966684Z  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-11-05T05:03:06.966689Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966700Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966698Z  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-11-05T05:03:06.966710Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966711Z  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-11-05T05:03:06.966720Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966726Z  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-11-05T05:03:06.966730Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966737Z  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-11-05T05:03:06.966740Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966747Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.966750Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966757Z  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-11-05T05:03:06.966760Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966770Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.966772Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966780Z  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-11-05T05:03:06.966784Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966791Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.966793Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966801Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966803Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966810Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966814Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966820Z  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-11-05T05:03:06.966824Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966830Z  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-11-05T05:03:06.966834Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966841Z  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-11-05T05:03:06.966844Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966853Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966851Z  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-11-05T05:03:06.966862Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966864Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966874Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966875Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966884Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966885Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966894Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966895Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966904Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966906Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966913Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966916Z  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-11-05T05:03:06.966923Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966928Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.966932Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966939Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966949Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.966958Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2025-11-05T05:03:06.966960Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.967021Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.967034Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.967044Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967055Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967065Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967075Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967085Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967084Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192
[INFO] [stdout] 2025-11-05T05:03:06.967095Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967106Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.967105Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967117Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967119Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.967127Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967133Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1
[INFO] [stdout] 2025-11-05T05:03:06.967137Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967146Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.967147Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967156Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.967157Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967166Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.967168Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967177Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.967178Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967193Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.967192Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967204Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967207Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-11-05T05:03:06.967214Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967220Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40
[INFO] [stdout] 2025-11-05T05:03:06.967232Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967234Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56
[INFO] [stdout] 2025-11-05T05:03:06.967242Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967247Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2
[INFO] [stdout] 2025-11-05T05:03:06.967252Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967262Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967260Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-11-05T05:03:06.967271Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967274Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17
[INFO] [stdout] 2025-11-05T05:03:06.967282Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967287Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17
[INFO] [stdout] 2025-11-05T05:03:06.967292Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967299Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17
[INFO] [stdout] 2025-11-05T05:03:06.966454Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967322Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967323Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17
[INFO] [stdout] 2025-11-05T05:03:06.967332Z  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-11-05T05:03:06.967337Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56
[INFO] [stdout] 2025-11-05T05:03:06.967343Z  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-11-05T05:03:06.967349Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40
[INFO] [stdout] 2025-11-05T05:03:06.967353Z  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-11-05T05:03:06.967366Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.967364Z  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-11-05T05:03:06.967376Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967379Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.967385Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967388Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.967395Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967398Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.967404Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967406Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.967413Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.970526Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.970555Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.970540Z  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-11-05T05:03:06.970565Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.970567Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.970576Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.970580Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.970585Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.970590Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.970593Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.970602Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.970601Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.970612Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.970612Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.970619Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.970623Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.970628Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.970634Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.970637Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.970645Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967424Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.966283Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.970685Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.970699Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.970721Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.970710Z  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-11-05T05:03:06.970732Z  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-11-05T05:03:06.970646Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.970754Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.970755Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.970766Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.970766Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.967302Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.970854Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.970863Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.970860Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.970872Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.970877Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.970880Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.970888Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.970889Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.970897Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.970900Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.970908Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2025-11-05T05:03:06.970909Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.970919Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.970928Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.970937Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.970946Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.970955Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.970962Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.970981Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.970992Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971000Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.971009Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.971018Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971019Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.971026Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971033Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.971035Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.971046Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=0
[INFO] [stdout] 2025-11-05T05:03:06.971049Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971058Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.971057Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.971067Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.971069Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.971077Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971080Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.971085Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971090Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.971094Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.971100Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971103Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971111Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.971111Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=0
[INFO] [stdout] 2025-11-05T05:03:06.971120Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.971124Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=39
[INFO] [stdout] 2025-11-05T05:03:06.971130Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971139Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971137Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=55
[INFO] [stdout] 2025-11-05T05:03:06.971147Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.971150Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=1
[INFO] [stdout] 2025-11-05T05:03:06.971157Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971165Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.971163Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=0
[INFO] [stdout] 2025-11-05T05:03:06.971176Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.971178Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=16
[INFO] [stdout] 2025-11-05T05:03:06.971186Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971190Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=16
[INFO] [stdout] 2025-11-05T05:03:06.971194Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971204Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.971203Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=16
[INFO] [stdout] 2025-11-05T05:03:06.971214Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971222Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.971224Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=16
[INFO] [stdout] 2025-11-05T05:03:06.971231Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.971241Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971237Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=55
[INFO] [stdout] 2025-11-05T05:03:06.971249Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971250Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=39
[INFO] [stdout] 2025-11-05T05:03:06.971258Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.971266Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.971268Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971274Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971276Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.971283Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.971285Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.971293Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.971297Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971300Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971305Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971309Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.971314Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.971319Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.971324Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971326Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971332Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.971335Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.971341Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.971345Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.971351Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971353Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971358Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971362Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.971367Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.971377Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971372Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.971385Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.971389Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971394Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.971398Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.971404Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971408Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.971412Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971415Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971421Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.971424Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.971431Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971434Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.971439Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.971441Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971448Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.971449Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.971457Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971482Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971493Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.971503Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971511Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.971520Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.971529Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.971537Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.971546Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.971556Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=17
[INFO] [stdout] 2025-11-05T05:03:06.971566Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.971579Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.971590Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.970836Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.971458Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.970791Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971625Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.971635Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971639Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.971650Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971651Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.971660Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971662Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971670Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971672Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971680Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971682Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971691Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971692Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971703Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971701Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971714Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971719Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971725Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971729Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971737Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971738Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971747Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971748Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971756Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971758Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971767Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971769Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971778Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971779Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971787Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971789Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971798Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971799Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971808Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971809Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971818Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971819Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971828Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971829Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971839Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971839Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971851Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971853Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971862Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971863Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971872Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971873Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971881Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971883Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971891Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971892Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971900Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971902Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971910Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971912Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2025-11-05T05:03:06.971919Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971929Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971938Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971949Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.971958Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2025-11-05T05:03:06.972028Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192
[INFO] [stdout] 2025-11-05T05:03:06.972046Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.972057Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.972070Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1
[INFO] [stdout] 2025-11-05T05:03:06.972080Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.972069Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=1
[INFO] [stdout] 2025-11-05T05:03:06.972091Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.972102Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.972100Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 0]
[INFO] [stdout] 2025-11-05T05:03:06.972113Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.972120Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 0
[INFO] [stdout] 2025-11-05T05:03:06.972124Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.972134Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=65
[INFO] [stdout] 2025-11-05T05:03:06.972136Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-11-05T05:03:06.972148Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40
[INFO] [stdout] 2025-11-05T05:03:06.972149Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 1]
[INFO] [stdout] 2025-11-05T05:03:06.972161Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56
[INFO] [stdout] 2025-11-05T05:03:06.972164Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 64
[INFO] [stdout] 2025-11-05T05:03:06.972173Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2
[INFO] [stdout] 2025-11-05T05:03:06.972177Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=257
[INFO] [stdout] 2025-11-05T05:03:06.972186Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-11-05T05:03:06.972192Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 4]
[INFO] [stdout] 2025-11-05T05:03:06.972200Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17
[INFO] [stdout] 2025-11-05T05:03:06.972207Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 256
[INFO] [stdout] 2025-11-05T05:03:06.972213Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17
[INFO] [stdout] 2025-11-05T05:03:06.972239Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17
[INFO] [stdout] 2025-11-05T05:03:06.972252Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17
[INFO] [stdout] 2025-11-05T05:03:06.972264Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56
[INFO] [stdout] 2025-11-05T05:03:06.972277Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40
[INFO] [stdout] 2025-11-05T05:03:06.972293Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.972311Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.972321Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.972331Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.970735Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.972339Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.972347Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.972357Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.972348Z  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-11-05T05:03:06.972364Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.972367Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.972373Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.972379Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972384Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.972389Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972392Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.972399Z  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-11-05T05:03:06.972401Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.972416Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.972412Z  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-11-05T05:03:06.972424Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.972425Z  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-11-05T05:03:06.972434Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.972436Z  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-11-05T05:03:06.972444Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.972448Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972453Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.972480Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.972458Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972493Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.972503Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.972501Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972512Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.972513Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972522Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.972523Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972529Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.972537Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.972534Z  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-11-05T05:03:06.972548Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.972549Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.972555Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.972559Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972565Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.972569Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.972574Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.972579Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.972582Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.972591Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.972590Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.972601Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.972602Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }]
[INFO] [stdout] 2025-11-05T05:03:06.972609Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.972613Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972618Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.972622Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972627Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.972632Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972635Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.972642Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972647Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.972652Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972657Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.972662Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972664Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.972672Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972674Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.972685Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.972682Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972693Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.972694Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972701Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.972704Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972712Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.972714Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972720Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.972724Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972729Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.972734Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972738Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.972744Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972746Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.972755Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.972754Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972765Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.972768Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972773Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.972777Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972782Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.972787Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972791Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.972797Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972799Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.972807Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972808Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.972817Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972819Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.972827Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972829Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.972837Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972839Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.972847Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972849Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.972857Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972858Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.972867Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972868Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.972877Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972879Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.972889Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972891Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.972899Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[]
[INFO] [stdout] 2025-11-05T05:03:06.972901Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.972909Z  INFO ramu_rs::ddr4: read_latency read_latency=20
[INFO] [stdout] 2025-11-05T05:03:06.972911Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.972919Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.972928Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.972938Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.972946Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.972955Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.972965Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.972974Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.972982Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.972991Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.972999Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.973008Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.973017Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973025Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973025Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192
[INFO] [stdout] 2025-11-05T05:03:06.973033Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973039Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973042Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973048Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.973050Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.973059Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.973060Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1
[INFO] [stdout] 2025-11-05T05:03:06.973072Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973073Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.973079Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973084Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.973089Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973094Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.973099Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973104Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.973107Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.973114Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.973116Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.973126Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973124Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-11-05T05:03:06.973134Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973137Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40
[INFO] [stdout] 2025-11-05T05:03:06.973142Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973152Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973149Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56
[INFO] [stdout] 2025-11-05T05:03:06.973159Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.973161Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2
[INFO] [stdout] 2025-11-05T05:03:06.973168Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.973174Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1
[INFO] [stdout] 2025-11-05T05:03:06.973179Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17
[INFO] [stdout] 2025-11-05T05:03:06.973189Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.973188Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17
[INFO] [stdout] 2025-11-05T05:03:06.973199Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.973201Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17
[INFO] [stdout] 2025-11-05T05:03:06.973213Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17
[INFO] [stdout] 2025-11-05T05:03:06.973210Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.973225Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17
[INFO] [stdout] 2025-11-05T05:03:06.973228Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.973238Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56
[INFO] [stdout] 2025-11-05T05:03:06.973241Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21
[INFO] [stdout] 2025-11-05T05:03:06.973250Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40
[INFO] [stdout] 2025-11-05T05:03:06.973253Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21
[INFO] [stdout] 2025-11-05T05:03:06.973266Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973267Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21
[INFO] [stdout] 2025-11-05T05:03:06.973274Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.973279Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21
[INFO] [stdout] 2025-11-05T05:03:06.973283Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.973293Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973291Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27
[INFO] [stdout] 2025-11-05T05:03:06.973300Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973305Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27
[INFO] [stdout] 2025-11-05T05:03:06.973309Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973320Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973319Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26
[INFO] [stdout] 2025-11-05T05:03:06.973328Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.973331Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38
[INFO] [stdout] 2025-11-05T05:03:06.973337Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.973346Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973345Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23
[INFO] [stdout] 2025-11-05T05:03:06.973353Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973357Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23
[INFO] [stdout] 2025-11-05T05:03:06.973362Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973372Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973371Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26
[INFO] [stdout] 2025-11-05T05:03:06.973380Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.973389Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.973398Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973393Z 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-11-05T05:03:06.973406Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973410Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973414Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973420Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973425Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973430Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973433Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.973440Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973442Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.973447Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973452Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973455Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973459Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973485Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973488Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973493Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973499Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973501Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973510Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973509Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.973517Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973518Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.973524Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973528Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973532Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973536Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973539Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973545Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973547Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973554Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973555Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973561Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.973564Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973570Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.973572Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973578Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973581Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973585Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973588Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973594Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973595Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973603Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973604Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973611Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.973613Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973620Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.973621Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973629Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973630Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973636Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973637Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973644Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973646Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973653Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973654Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973660Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.973662Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973669Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.973670Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973677Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973680Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973684Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973687Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973692Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973695Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973701Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973704Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973708Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.973711Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973716Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.973719Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973725Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973728Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973732Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973734Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973740Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973742Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973749Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973751Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973756Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.973758Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973764Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.973765Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973773Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973774Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973780Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973781Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.973788Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973941Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.973794Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.973955Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.973962Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.973983Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.973991Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.973963Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.974005Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.974008Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.974015Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.974018Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974022Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.974026Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.974030Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.974034Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.974039Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.974042Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974046Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.974049Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.974055Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.974057Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.974065Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.974066Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974073Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.974074Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.974082Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.974083Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.974092Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.974094Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974100Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.974101Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.974109Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.974110Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.974119Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.974126Z 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-11-05T05:03:06.974128Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.974136Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974138Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.974143Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.974147Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.974151Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.974154Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.974160Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974163Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.974167Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.974171Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.974175Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.974179Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.974183Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974187Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.974190Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.974197Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=16
[INFO] [stdout] 2025-11-05T05:03:06.974198Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.974205Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.974207Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40
[INFO] [stdout] 2025-11-05T05:03:06.974215Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.974222Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.974225Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.974232Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.974235Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.974243Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.974247Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=20
[INFO] [stdout] 2025-11-05T05:03:06.974253Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-11-05T05:03:06.974258Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=20
[INFO] [stdout] 2025-11-05T05:03:06.974264Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56
[INFO] [stdout] 2025-11-05T05:03:06.974271Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=20
[INFO] [stdout] 2025-11-05T05:03:06.974275Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56
[INFO] [stdout] 2025-11-05T05:03:06.974282Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=20
[INFO] [stdout] 2025-11-05T05:03:06.974287Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56
[INFO] [stdout] 2025-11-05T05:03:06.974294Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=26
[INFO] [stdout] 2025-11-05T05:03:06.974299Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974307Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.974305Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=26
[INFO] [stdout] 2025-11-05T05:03:06.974315Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974317Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=39 future=25
[INFO] [stdout] 2025-11-05T05:03:06.974322Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.974330Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974329Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=1 future=37
[INFO] [stdout] 2025-11-05T05:03:06.974337Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.974341Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=22
[INFO] [stdout] 2025-11-05T05:03:06.974347Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974354Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.974353Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=22
[INFO] [stdout] 2025-11-05T05:03:06.974362Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974365Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=39 future=25
[INFO] [stdout] 2025-11-05T05:03:06.974370Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.974378Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974378Z 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-11-05T05:03:06.974385Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.974393Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974400Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.974408Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974415Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.974423Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974430Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.974438Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974445Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.974453Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974460Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.974487Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974495Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.974504Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974511Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.974521Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974531Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.974541Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974548Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.974558Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974565Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.974575Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56
[INFO] [stdout] 2025-11-05T05:03:06.974584Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.974594Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.974604Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.974614Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-11-05T05:03:06.974624Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.974633Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56
[INFO] [stdout] 2025-11-05T05:03:06.974646Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95
[INFO] [stdout] 2025-11-05T05:03:06.974658Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111
[INFO] [stdout] 2025-11-05T05:03:06.974670Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57
[INFO] [stdout] 2025-11-05T05:03:06.974684Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56
[INFO] [stdout] 2025-11-05T05:03:06.974697Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72
[INFO] [stdout] 2025-11-05T05:03:06.974710Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72
[INFO] [stdout] 2025-11-05T05:03:06.974722Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72
[INFO] [stdout] 2025-11-05T05:03:06.974734Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72
[INFO] [stdout] 2025-11-05T05:03:06.974745Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111
[INFO] [stdout] 2025-11-05T05:03:06.974757Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95
[INFO] [stdout] 2025-11-05T05:03:06.974771Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974780Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.974790Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.974800Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974807Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.974816Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.974825Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974833Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.974841Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.974851Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974859Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.974868Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.974877Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974885Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.974895Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.974905Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974912Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.974921Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.974931Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974939Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.974949Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.974959Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.974967Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.974976Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.974985Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.975002Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.975015Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.975025Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.975033Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.975042Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.975052Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.975060Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.975069Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.975078Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.975086Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.975096Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.975105Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.975113Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.975122Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.975132Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.975140Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.975148Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.975158Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.975166Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.975175Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.975184Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.975193Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.975202Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.975212Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=72
[INFO] [stdout] 2025-11-05T05:03:06.975230Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.975242Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.975252Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.975263Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-11-05T05:03:06.975278Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=76
[INFO] [stdout] 2025-11-05T05:03:06.975291Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=76
[INFO] [stdout] 2025-11-05T05:03:06.975304Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=27 future=76
[INFO] [stdout] 2025-11-05T05:03:06.975316Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=27 future=76
[INFO] [stdout] 2025-11-05T05:03:06.975329Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=21 future=91
[INFO] [stdout] 2025-11-05T05:03:06.975342Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=21 future=91
[INFO] [stdout] 2025-11-05T05:03:06.975354Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=95 future=106
[INFO] [stdout] 2025-11-05T05:03:06.975367Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=57 future=106
[INFO] [stdout] 2025-11-05T05:03:06.975380Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=78
[INFO] [stdout] 2025-11-05T05:03:06.975393Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=78
[INFO] [stdout] 2025-11-05T05:03:06.975406Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=23 future=97
[INFO] [stdout] 2025-11-05T05:03:06.975420Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=23 future=97
[INFO] [stdout] 2025-11-05T05:03:06.975433Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=95 future=106
[INFO] [stdout] 2025-11-05T05:03:06.975460Z 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-11-05T05:03:06.975576Z 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-11-05T05:03:06.973804Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.975892Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=21
[INFO] [stdout] 2025-11-05T05:03:06.975930Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=21
[INFO] [stdout] 2025-11-05T05:03:06.975945Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=0 future=21
[INFO] [stdout] 2025-11-05T05:03:06.975958Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=0 future=21
[INFO] [stdout] 2025-11-05T05:03:06.975985Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=0 future=36
[INFO] [stdout] test ddr4::tests::test_address ... ok
[INFO] [stdout] 2025-11-05T05:03:06.975998Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=0 future=36
[INFO] [stdout] 2025-11-05T05:03:06.976053Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=40 future=51
[INFO] [stdout] 2025-11-05T05:03:06.976071Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=2 future=51
[INFO] [stdout] 2025-11-05T05:03:06.976084Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=23
[INFO] [stdout] 2025-11-05T05:03:06.976097Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=23
[INFO] [stdout] 2025-11-05T05:03:06.976110Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=0 future=42
[INFO] [stdout] 2025-11-05T05:03:06.976122Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=0 future=42
[INFO] [stdout] 2025-11-05T05:03:06.976177Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=40 future=51
[INFO] [stdout] 2025-11-05T05:03:06.976224Z 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-11-05T05:03:06.976269Z 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-11-05T05:03:06.976319Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.976360Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.976410Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.976478Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.976537Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.976576Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.976608Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.976647Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.976674Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.976701Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.976725Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.976758Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.976787Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.976812Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.976840Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.976878Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.976906Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.976935Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.976963Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] test test::test_memory_read_and_write ... ok
[INFO] [stdout] 2025-11-05T05:03:06.977032Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.977042Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977052Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.977059Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.977067Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977076Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.977084Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.977092Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977101Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.977108Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.977116Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977125Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.977132Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.977140Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977149Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.977156Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.977164Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977173Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.977180Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.977188Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977197Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.977204Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.977212Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977221Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.977230Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.977238Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977247Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.977255Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.977265Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977274Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.977281Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.977289Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977298Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.977305Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.977313Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977323Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.977330Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.977338Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977347Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.977356Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.977364Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977374Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.977382Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.977391Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977401Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.977409Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.977417Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977427Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.977434Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.977443Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977453Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.977516Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.977550Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.977577Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.977608Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.978512Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.978527Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.978538Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.978545Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.978553Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.978562Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.978569Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.978578Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.978586Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.978594Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.978602Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.978611Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.978618Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.978627Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.978635Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.978642Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.978651Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.978659Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.978667Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.978675Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.978684Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.978691Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.978699Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.978708Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.978715Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.978723Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.978732Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.978740Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0
[INFO] [stdout] 2025-11-05T05:03:06.978748Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.978759Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17
[INFO] [stdout] 2025-11-05T05:03:06.978768Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.978778Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.978788Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.978797Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.978809Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21
[INFO] [stdout] 2025-11-05T05:03:06.978821Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21
[INFO] [stdout] 2025-11-05T05:03:06.978834Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21
[INFO] [stdout] 2025-11-05T05:03:06.978846Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21
[INFO] [stdout] 2025-11-05T05:03:06.978858Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27
[INFO] [stdout] 2025-11-05T05:03:06.978869Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27
[INFO] [stdout] 2025-11-05T05:03:06.978881Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26
[INFO] [stdout] 2025-11-05T05:03:06.978893Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38
[INFO] [stdout] 2025-11-05T05:03:06.978905Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23
[INFO] [stdout] 2025-11-05T05:03:06.978917Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23
[INFO] [stdout] 2025-11-05T05:03:06.978929Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26
[INFO] [stdout] 2025-11-05T05:03:06.978943Z 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-11-05T05:03:06.978957Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.978965Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.978981Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.978991Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.978998Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979006Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979015Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979022Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979031Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979039Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979047Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979055Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979064Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979071Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979079Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979089Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979096Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979104Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979113Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979120Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979128Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979137Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979144Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979152Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979161Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979169Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979177Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979186Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979193Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979202Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979211Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979218Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979226Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979235Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979243Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979251Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979260Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979267Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979276Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979284Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979292Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979300Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979309Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979316Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979324Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979333Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979341Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979349Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979358Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979365Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979373Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979382Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979389Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979398Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979406Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979414Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979422Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979432Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.979440Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979448Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.977461Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979570Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979601Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.979644Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979674Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979703Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.979736Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979762Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979790Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.979821Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979853Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979885Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.979915Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.979941Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.979984Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.980016Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.980044Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.980077Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.980108Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.980134Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.980159Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.980189Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.980220Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.980251Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.980283Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.980308Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.980342Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.980374Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.980398Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.980423Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.980447Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.980494Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.980524Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=51
[INFO] [stdout] 2025-11-05T05:03:06.980548Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.980574Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.980607Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.980634Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-11-05T05:03:06.980666Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=67
[INFO] [stdout] 2025-11-05T05:03:06.980696Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=67
[INFO] [stdout] 2025-11-05T05:03:06.980734Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=67
[INFO] [stdout] 2025-11-05T05:03:06.980766Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.980790Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.980820Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.980851Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.980877Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.980901Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.980926Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.981522Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.981539Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.981548Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.981558Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.981565Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.981574Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.981582Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.981591Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.981599Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.981609Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.981617Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.981626Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.981634Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.981643Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.981651Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.981660Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.981668Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.981678Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.981685Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.981694Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.981702Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.981712Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.981719Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.981729Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.981736Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.981746Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=67
[INFO] [stdout] 2025-11-05T05:03:06.981755Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.981766Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.981778Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.981788Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-11-05T05:03:06.981798Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.981807Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=67
[INFO] [stdout] 2025-11-05T05:03:06.981820Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=51 future=106
[INFO] [stdout] 2025-11-05T05:03:06.981831Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=67 future=122
[INFO] [stdout] 2025-11-05T05:03:06.981843Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=51 future=68
[INFO] [stdout] 2025-11-05T05:03:06.981856Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=67
[INFO] [stdout] 2025-11-05T05:03:06.981868Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=83
[INFO] [stdout] 2025-11-05T05:03:06.981880Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=83
[INFO] [stdout] 2025-11-05T05:03:06.981891Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=83
[INFO] [stdout] 2025-11-05T05:03:06.981903Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=83
[INFO] [stdout] 2025-11-05T05:03:06.981915Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=67 future=122
[INFO] [stdout] 2025-11-05T05:03:06.981926Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=51 future=106
[INFO] [stdout] 2025-11-05T05:03:06.981941Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.981948Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.981957Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.981966Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.981987Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.981996Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.982006Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.982014Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.982022Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.982031Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.982038Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.982046Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.982055Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.982062Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.982070Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.982079Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.982086Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.982094Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.982103Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.982111Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.982119Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.982128Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.982135Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.982143Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.982152Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.982159Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.982167Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.982176Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.982183Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.982192Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.982200Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.982208Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.982216Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.982224Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.982233Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.982241Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.982250Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.982257Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.982265Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.982274Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.982281Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.982290Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.982299Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.982305Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.982314Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.982322Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR
[INFO] [stdout] 2025-11-05T05:03:06.982330Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.982338Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR
[INFO] [stdout] 2025-11-05T05:03:06.982347Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=83
[INFO] [stdout] 2025-11-05T05:03:06.982355Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.982365Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.982374Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.982385Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-11-05T05:03:06.982397Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=21 future=87
[INFO] [stdout] 2025-11-05T05:03:06.982409Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=21 future=87
[INFO] [stdout] 2025-11-05T05:03:06.982422Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=21 future=87
[INFO] [stdout] 2025-11-05T05:03:06.982435Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=21 future=87
[INFO] [stdout] 2025-11-05T05:03:06.982447Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=36 future=102
[INFO] [stdout] 2025-11-05T05:03:06.981495Z 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-11-05T05:03:06.982544Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.982573Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.982607Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.982634Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.982658Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.982688Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.982726Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.982750Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.982774Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE
[INFO] [stdout] 2025-11-05T05:03:06.982807Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40
[INFO] [stdout] 2025-11-05T05:03:06.982839Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.982866Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.982892Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.982918Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-11-05T05:03:06.982957Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56
[INFO] [stdout] 2025-11-05T05:03:06.983010Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56
[INFO] [stdout] 2025-11-05T05:03:06.983042Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56
[INFO] [stdout] 2025-11-05T05:03:06.983082Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983106Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.983138Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983162Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.983195Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983225Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.983252Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983283Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.983315Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983345Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.983371Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983396Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.983433Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983457Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.983518Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983527Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.983536Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983543Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.983552Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983559Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.983568Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983575Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.983584Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983591Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.983600Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983607Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.983615Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983622Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.983631Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983638Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.983647Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983654Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT
[INFO] [stdout] 2025-11-05T05:03:06.983663Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56
[INFO] [stdout] 2025-11-05T05:03:06.983671Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.983681Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.983691Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.983700Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-11-05T05:03:06.983710Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.983719Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56
[INFO] [stdout] 2025-11-05T05:03:06.983731Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95
[INFO] [stdout] 2025-11-05T05:03:06.983744Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111
[INFO] [stdout] 2025-11-05T05:03:06.983756Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57
[INFO] [stdout] 2025-11-05T05:03:06.983769Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56
[INFO] [stdout] 2025-11-05T05:03:06.983782Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72
[INFO] [stdout] 2025-11-05T05:03:06.983794Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72
[INFO] [stdout] 2025-11-05T05:03:06.983807Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72
[INFO] [stdout] 2025-11-05T05:03:06.983819Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72
[INFO] [stdout] 2025-11-05T05:03:06.983831Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111
[INFO] [stdout] 2025-11-05T05:03:06.983843Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95
[INFO] [stdout] 2025-11-05T05:03:06.983858Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983866Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.983874Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.983884Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983890Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.983899Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.983909Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983916Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.983923Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.983933Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983940Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.983948Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.983958Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983966Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.983981Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.983991Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.983998Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.984006Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.984015Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.984022Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.984031Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.984039Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.984047Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.984055Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.984064Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.984072Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.984081Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.984090Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.984097Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.984105Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.984114Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.984122Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.984130Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.984139Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.984147Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.984155Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.984163Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.984171Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.984179Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.984188Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.984197Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.984206Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.984215Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.984222Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.984231Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.984240Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD
[INFO] [stdout] 2025-11-05T05:03:06.984248Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1
[INFO] [stdout] 2025-11-05T05:03:06.984257Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD
[INFO] [stdout] 2025-11-05T05:03:06.984266Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=72
[INFO] [stdout] 2025-11-05T05:03:06.984275Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.984286Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.984296Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0
[INFO] [stdout] 2025-11-05T05:03:06.984306Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1
[INFO] [stdout] 2025-11-05T05:03:06.984318Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=21 future=76
[INFO] [stdout] 2025-11-05T05:03:06.984331Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=21 future=76
[INFO] [stdout] 2025-11-05T05:03:06.984344Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=21 future=76
[INFO] [stdout] 2025-11-05T05:03:06.984356Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=21 future=76
[INFO] [stdout] 2025-11-05T05:03:06.984368Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=27 future=82
[INFO] [stdout] 2025-11-05T05:03:06.984380Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=27 future=82
[INFO] [stdout] 2025-11-05T05:03:06.984392Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=95 future=81
[INFO] [stdout] 2025-11-05T05:03:06.984404Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=57 future=93
[INFO] [stdout] 2025-11-05T05:03:06.984418Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=23 future=78
[INFO] [stdout] 2025-11-05T05:03:06.984430Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=23 future=78
[INFO] [stdout] 2025-11-05T05:03:06.984442Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=95 future=81
[INFO] [stdout] 2025-11-05T05:03:06.984457Z 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-11-05T05:03:06.984488Z 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] 2025-11-05T05:03:06.982461Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=36 future=102
[INFO] [stdout] 2025-11-05T05:03:06.984687Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=106 future=117
[INFO] [stdout] 2025-11-05T05:03:06.984701Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=68 future=117
[INFO] [stdout] 2025-11-05T05:03:06.984715Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=23 future=89
[INFO] [stdout] 2025-11-05T05:03:06.984726Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=23 future=89
[INFO] [stdout] 2025-11-05T05:03:06.984739Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=42 future=108
[INFO] [stdout] 2025-11-05T05:03:06.984750Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=42 future=108
[INFO] [stdout] 2025-11-05T05:03:06.984764Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=106 future=117
[INFO] [stdout] 2025-11-05T05:03:06.984779Z 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-11-05T05:03:06.984789Z 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_diffrent_row ... ok
[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] Failed to init tracing: a global default trace dispatcher has already been set
[INFO] [stdout] 
[INFO] [stdout] thread 'controller::tests::test_controller_simple_read' (25) panicked at src/controller.rs:300:9:
[INFO] [stdout] assertion failed: controller.finished_queue.is_empty()
[INFO] [stdout] stack backtrace:
[INFO] [stdout]    0:     0x56fc5b62a702 - std::backtrace_rs::backtrace::libunwind::trace::h16acf28769fcd909
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/../../backtrace/src/backtrace/libunwind.rs:117:9
[INFO] [stdout]    1:     0x56fc5b62a702 - std::backtrace_rs::backtrace::trace_unsynchronized::hb5541aa5d4f92513
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/../../backtrace/src/backtrace/mod.rs:66:14
[INFO] [stdout]    2:     0x56fc5b62a702 - std::sys::backtrace::_print_fmt::h8ac8268cb667a306
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/sys/backtrace.rs:66:9
[INFO] [stdout]    3:     0x56fc5b62a702 - <std::sys::backtrace::BacktraceLock::print::DisplayBacktrace as core::fmt::Display>::fmt::h47627beda0767f4c
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/sys/backtrace.rs:39:26
[INFO] [stdout]    4:     0x56fc5b63b9ff - core::fmt::rt::Argument::fmt::h686a01ad57c1c92a
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/core/src/fmt/rt.rs:173:76
[INFO] [stdout]    5:     0x56fc5b63b9ff - core::fmt::write::h8a63064c67176fd8
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/core/src/fmt/mod.rs:1469:25
[INFO] [stdout]    6:     0x56fc5b5f7e33 - std::io::default_write_fmt::hd4797e693c0ec256
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/io/mod.rs:639:11
[INFO] [stdout]    7:     0x56fc5b5f7e33 - std::io::Write::write_fmt::h791e240ad2720c99
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/io/mod.rs:1954:13
[INFO] [stdout]    8:     0x56fc5b603dc2 - std::sys::backtrace::BacktraceLock::print::h4634d27c0afbaebb
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/sys/backtrace.rs:42:9
[INFO] [stdout]    9:     0x56fc5b608a0f - std::panicking::default_hook::{{closure}}::h23e0299d4738b766
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/panicking.rs:301:27
[INFO] [stdout]   10:     0x56fc5b6088a1 - std::panicking::default_hook::hfeec6294e8751b62
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/panicking.rs:325:9
[INFO] [stdout]   11:     0x56fc5b428bfe - <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call::h3f5a16438cee2b4e
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/alloc/src/boxed.rs:2019:9
[INFO] [stdout]   12:     0x56fc5b428bfe - test::test_main_with_exit_callback::{{closure}}::h9214498cef9aafc5
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/test/src/lib.rs:145:21
[INFO] [stdout]   13:     0x56fc5b60901f - <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call::hdb18da3e68df7464
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/alloc/src/boxed.rs:2019:9
[INFO] [stdout]   14:     0x56fc5b60901f - std::panicking::panic_with_hook::hd57cd463d793ed79
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/panicking.rs:842:13
[INFO] [stdout]   15:     0x56fc5b608e46 - std::panicking::panic_handler::{{closure}}::hddd6216c3fddee3b
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/panicking.rs:700:13
[INFO] [stdout]   16:     0x56fc5b603ef9 - std::sys::backtrace::__rust_end_short_backtrace::h5e7a56f283378525
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/sys/backtrace.rs:174:18
[INFO] [stdout]   17:     0x56fc5b5ec5dd - __rustc[256c90bb7e548b45]::rust_begin_unwind
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/panicking.rs:698:5
[INFO] [stdout]   18:     0x56fc5b645130 - core::panicking::panic_fmt::hf19c198748ef6a95
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/core/src/panicking.rs:80:14
[INFO] [stdout]   19:     0x56fc5b64510c - core::panicking::panic::h5387b4c27e81d0dd
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/core/src/panicking.rs:150:5
[INFO] [stdout]   20:     0x56fc5b3ed01f - ramu_rs::controller::tests::test_controller_simple_read::h6709fea29132a738
[INFO] [stdout]                                at /opt/rustwide/workdir/src/controller.rs:300:9
[INFO] [stdout]   21:     0x56fc5b3ed127 - ramu_rs::controller::tests::test_controller_simple_read::{{closure}}::h12d7adb3a4f5c504
[INFO] [stdout]                                at /opt/rustwide/workdir/src/controller.rs:277:37
[INFO] [stdout]   22:     0x56fc5b3e6d46 - core::ops::function::FnOnce::call_once::he7c41eec339b65e3
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/core/src/ops/function.rs:250:5
[INFO] [stdout]   23:     0x56fc5b428a4b - core::ops::function::FnOnce::call_once::h43f43c5185cf39c2
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/core/src/ops/function.rs:250:5
[INFO] [stdout]   24:     0x56fc5b428a4b - test::__rust_begin_short_backtrace::hc4fa634eb2764bdc
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/test/src/lib.rs:663:18
[INFO] [stdout]   25:     0x56fc5b43d068 - test::run_test_in_process::{{closure}}::h9f4b799a5211b72a
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/test/src/lib.rs:686:74
[INFO] [stdout]   26:     0x56fc5b43d068 - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::ha572bf7dc5230a8f
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/core/src/panic/unwind_safe.rs:274:9
[INFO] [stdout]   27:     0x56fc5b43d068 - std::panicking::catch_unwind::do_call::hfd6ff51f25dd177b
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/panicking.rs:590:40
[INFO] [stdout]   28:     0x56fc5b43d068 - std::panicking::catch_unwind::h8609b446221def5f
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/panicking.rs:553:19
[INFO] [stdout]   29:     0x56fc5b43d068 - std::panic::catch_unwind::h362f73cc48531e26
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/panic.rs:359:14
[INFO] [stdout]   30:     0x56fc5b43d068 - test::run_test_in_process::hf52fd21d696aae67
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/test/src/lib.rs:686:27
[INFO] [stdout]   31:     0x56fc5b43d068 - test::run_test::{{closure}}::h7e780b8354e6d007
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/test/src/lib.rs:607:43
[INFO] [stdout]   32:     0x56fc5b415e34 - test::run_test::{{closure}}::hdc2695f2276aad3e
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/test/src/lib.rs:637:41
[INFO] [stdout]   33:     0x56fc5b415e34 - std::sys::backtrace::__rust_begin_short_backtrace::h2555b2113ed90fc9
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/sys/backtrace.rs:158:18
[INFO] [stdout]   34:     0x56fc5b41976a - std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}::h99800d480987dfb6
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/thread/mod.rs:562:17
[INFO] [stdout]   35:     0x56fc5b41976a - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::hbbb69b5294b2221b
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/core/src/panic/unwind_safe.rs:274:9
[INFO] [stdout]   36:     0x56fc5b41976a - std::panicking::catch_unwind::do_call::h495689350c27df20
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/panicking.rs:590:40
[INFO] [stdout]   37:     0x56fc5b41976a - std::panicking::catch_unwind::hf22437c51d1b3740
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/panicking.rs:553:19
[INFO] [stdout]   38:     0x56fc5b41976a - std::panic::catch_unwind::habda1a57de8231f8
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/panic.rs:359:14
[INFO] [stdout]   39:     0x56fc5b41976a - std::thread::Builder::spawn_unchecked_::{{closure}}::h5833d8dda8c7e80b
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/thread/mod.rs:560:30
[INFO] [stdout]   40:     0x56fc5b41976a - core::ops::function::FnOnce::call_once{{vtable.shim}}::ha2910283a5058402
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/core/src/ops/function.rs:250:5
[INFO] [stdout]   41:     0x56fc5b5ff1ef - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::he4d85cb537521972
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/alloc/src/boxed.rs:2005:9
[INFO] [stdout]   42:     0x56fc5b5ff1ef - std::sys::thread::unix::Thread::new::thread_start::hbaf586a9e50a98cd
[INFO] [stdout]                                at /rustc/3b4dd9bf1410f8da6329baa36ce5e37673cbbd1f/library/std/src/sys/thread/unix.rs:126:17
[INFO] [stderr] error: test failed, to rerun pass `--lib`
[INFO] [stdout]   43:     0x7e05f4464aa4 - <unknown>
[INFO] [stdout]   44:     0x7e05f44f1a64 - 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" "408177e6587578748fe180a8275c75b8f8443be2e58c58019a4a08d4fdd313b5", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "408177e6587578748fe180a8275c75b8f8443be2e58c58019a4a08d4fdd313b5", kill_on_drop: false }`
[INFO] [stdout] 408177e6587578748fe180a8275c75b8f8443be2e58c58019a4a08d4fdd313b5