[INFO] fetching crate ramu_rs 0.1.1... [INFO] testing ramu_rs-0.1.1 against master#cdb45c87e2cd43495379f7e867e3cc15dcee9f93 for pr-145838-1 [INFO] extracting crate ramu_rs 0.1.1 into /workspace/builds/worker-2-tc1/source [INFO] started tweaking crates.io crate ramu_rs 0.1.1 [INFO] finished tweaking crates.io crate ramu_rs 0.1.1 [INFO] tweaked toml for crates.io crate ramu_rs 0.1.1 written to /workspace/builds/worker-2-tc1/source/Cargo.toml [INFO] validating manifest of crates.io crate ramu_rs 0.1.1 on toolchain cdb45c87e2cd43495379f7e867e3cc15dcee9f93 [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "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" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "generate-lockfile" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] [stderr] Updating crates.io index [INFO] [stderr] Locking 78 packages to latest compatible versions [INFO] [stderr] Adding enum-as-inner v0.5.1 (available: v0.6.1) [INFO] [stderr] Adding num_enum v0.5.11 (available: v0.7.4) [INFO] [stderr] Adding toml v0.5.11 (available: v0.9.5) [INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }` [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }` [INFO] [stdout] ab3c77abf82e24666e3fb529a4327d62e8980a03e263b7c50a6482939766589c [INFO] running `Command { std: "docker" "start" "-a" "ab3c77abf82e24666e3fb529a4327d62e8980a03e263b7c50a6482939766589c", kill_on_drop: false }` [INFO] running `Command { std: "docker" "inspect" "ab3c77abf82e24666e3fb529a4327d62e8980a03e263b7c50a6482939766589c", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "ab3c77abf82e24666e3fb529a4327d62e8980a03e263b7c50a6482939766589c", kill_on_drop: false }` [INFO] [stdout] ab3c77abf82e24666e3fb529a4327d62e8980a03e263b7c50a6482939766589c [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "build" "--frozen" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 2936da65d153b6ad1942a5fb76b6721bb00c1b4f579680f7cf6e03720b0eb4b9 [INFO] running `Command { std: "docker" "start" "-a" "2936da65d153b6ad1942a5fb76b6721bb00c1b4f579680f7cf6e03720b0eb4b9", kill_on_drop: false }` [INFO] [stderr] Compiling winnow v0.5.40 [INFO] [stderr] Compiling cxxbridge-flags v1.0.173 [INFO] [stderr] Compiling foldhash v0.2.0 [INFO] [stderr] Compiling link-cplusplus v1.0.10 [INFO] [stderr] Compiling cxxbridge-macro v1.0.173 [INFO] [stderr] Compiling enum-as-inner v0.5.1 [INFO] [stderr] Compiling toml v0.5.11 [INFO] [stderr] Compiling cxx v1.0.173 [INFO] [stderr] Compiling toml_edit v0.19.15 [INFO] [stderr] Compiling proc-macro-crate v1.3.1 [INFO] [stderr] Compiling num_enum_derive v0.5.11 [INFO] [stderr] Compiling num_enum v0.5.11 [INFO] [stderr] Compiling ramu_rs v0.1.1 (/opt/rustwide/workdir) [INFO] [stderr] Finished `dev` profile [unoptimized + debuginfo] target(s) in 7.47s [INFO] running `Command { std: "docker" "inspect" "2936da65d153b6ad1942a5fb76b6721bb00c1b4f579680f7cf6e03720b0eb4b9", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "2936da65d153b6ad1942a5fb76b6721bb00c1b4f579680f7cf6e03720b0eb4b9", kill_on_drop: false }` [INFO] [stdout] 2936da65d153b6ad1942a5fb76b6721bb00c1b4f579680f7cf6e03720b0eb4b9 [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }` [INFO] [stdout] 50308e1e96888f6f62703c0b0828ede32a751469cb0198e667c017d395a2880e [INFO] running `Command { std: "docker" "start" "-a" "50308e1e96888f6f62703c0b0828ede32a751469cb0198e667c017d395a2880e", 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.52s [INFO] running `Command { std: "docker" "inspect" "50308e1e96888f6f62703c0b0828ede32a751469cb0198e667c017d395a2880e", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "50308e1e96888f6f62703c0b0828ede32a751469cb0198e667c017d395a2880e", kill_on_drop: false }` [INFO] [stdout] 50308e1e96888f6f62703c0b0828ede32a751469cb0198e667c017d395a2880e [INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-2-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:7ad1b28ee6f5f7f699f6cf7015098d6ccdd96d6f2d78dd06228f5b4c9faf309c" "/opt/rustwide/cargo-home/bin/cargo" "+cdb45c87e2cd43495379f7e867e3cc15dcee9f93" "test" "--frozen", kill_on_drop: false }` [INFO] [stdout] 18584cf976070e6815fcd360f467e7ab0360ce11739c201e2b1c8d90ef1a655d [INFO] running `Command { std: "docker" "start" "-a" "18584cf976070e6815fcd360f467e7ab0360ce11739c201e2b1c8d90ef1a655d", kill_on_drop: false }` [INFO] [stderr] Finished `test` profile [unoptimized + debuginfo] target(s) in 0.06s [INFO] [stderr] Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/ramu_rs-fe9091c3870730f3) [INFO] [stdout] [INFO] [stdout] running 8 tests [INFO] [stdout] 2025-09-01T11:28:41.207776Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] test config::tests::dum_config ... ignored [INFO] [stdout] test scheduler::tests::test ... ok2025-09-01T11:28:41.207924Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] [INFO] [stdout] 2025-09-01T11:28:41.207938Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-09-01T11:28:41.207957Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-09-01T11:28:41.207971Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-09-01T11:28:41.208005Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-09-01T11:28:41.208017Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-09-01T11:28:41.208054Z  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-09-01T11:28:41.208075Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-09-01T11:28:41.208094Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-09-01T11:28:41.208012Z  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-09-01T11:28:41.208094Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-09-01T11:28:41.208117Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208015Z  INFO ramu_rs::ddr4: building ddr4 [INFO] [stdout] 2025-09-01T11:28:41.208127Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-09-01T11:28:41.208135Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208140Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-09-01T11:28:41.208141Z  INFO ramu_rs::ddr4: addr_size addr_size=[1, 1, 4, 4, 32768, 128] [INFO] [stdout] 2025-09-01T11:28:41.208146Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208150Z  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-09-01T11:28:41.208156Z  INFO ramu_rs::ddr4: addr_bits addr_bits=[0, 0, 2, 2, 15, 7] [INFO] [stdout] 2025-09-01T11:28:41.208158Z  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-09-01T11:28:41.208170Z  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-09-01T11:28:41.208176Z  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-09-01T11:28:41.208181Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208187Z  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-09-01T11:28:41.208194Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208198Z  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-09-01T11:28:41.208206Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208239Z  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-09-01T11:28:41.208229Z  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-09-01T11:28:41.208253Z  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-09-01T11:28:41.208206Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208276Z  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-09-01T11:28:41.208289Z  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-09-01T11:28:41.208295Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208306Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208317Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208316Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208313Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208210Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208327Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208330Z  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-09-01T11:28:41.208333Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208338Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208342Z  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-09-01T11:28:41.208342Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208349Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208355Z  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-09-01T11:28:41.208146Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=ACT timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208346Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208381Z  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-09-01T11:28:41.208357Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208361Z  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] test utils::tests::test_addr ... 2025-09-01T11:28:41.208394Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208398Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208405Z  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-09-01T11:28:41.208391Z  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-09-01T11:28:41.208413Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] ok [INFO] [stdout] 2025-09-01T11:28:41.208429Z  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-09-01T11:28:41.208389Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208434Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208435Z  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-09-01T11:28:41.208412Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208468Z  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-09-01T11:28:41.208462Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208489Z  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-09-01T11:28:41.208506Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208464Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208521Z  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-09-01T11:28:41.208488Z  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-09-01T11:28:41.208533Z  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-09-01T11:28:41.208443Z  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-09-01T11:28:41.208556Z  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-09-01T11:28:41.208538Z  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-09-01T11:28:41.208564Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208555Z  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-09-01T11:28:41.208596Z  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-09-01T11:28:41.208603Z  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-09-01T11:28:41.208611Z  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-09-01T11:28:41.208584Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208619Z  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-09-01T11:28:41.208623Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208629Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208634Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208633Z  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-09-01T11:28:41.208643Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208644Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208646Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.208655Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208657Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208658Z  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-09-01T11:28:41.208668Z  INFO ramu_rs::ddr4: timing_command level=Channel cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208578Z  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-09-01T11:28:41.208690Z  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-09-01T11:28:41.208667Z  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-09-01T11:28:41.208694Z  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-09-01T11:28:41.208717Z  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-09-01T11:28:41.208724Z  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-09-01T11:28:41.208705Z  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-09-01T11:28:41.208733Z  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-09-01T11:28:41.208739Z  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-09-01T11:28:41.208742Z  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-09-01T11:28:41.208813Z  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-09-01T11:28:41.208832Z  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-09-01T11:28:41.208830Z  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-09-01T11:28:41.208844Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.208849Z  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-09-01T11:28:41.208855Z  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-09-01T11:28:41.208863Z  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-09-01T11:28:41.208870Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.208513Z  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-09-01T11:28:41.208878Z  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-09-01T11:28:41.208882Z  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-09-01T11:28:41.208891Z  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-09-01T11:28:41.208672Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.208914Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.208923Z  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-09-01T11:28:41.208746Z  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-09-01T11:28:41.208937Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.208949Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208893Z  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-09-01T11:28:41.208960Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.208927Z  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-09-01T11:28:41.208971Z  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-09-01T11:28:41.208970Z  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-09-01T11:28:41.208985Z  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-09-01T11:28:41.208986Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.208990Z  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-09-01T11:28:41.208955Z  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-09-01T11:28:41.208997Z  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-09-01T11:28:41.208999Z  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-09-01T11:28:41.209005Z  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-09-01T11:28:41.209011Z  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-09-01T11:28:41.209016Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.209013Z  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-09-01T11:28:41.209024Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209022Z  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-09-01T11:28:41.209027Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209036Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209034Z  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-09-01T11:28:41.209038Z  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-09-01T11:28:41.209047Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209049Z  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-09-01T11:28:41.209057Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.209039Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209070Z  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-09-01T11:28:41.209088Z  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-09-01T11:28:41.209085Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.209101Z  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-09-01T11:28:41.209102Z  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-09-01T11:28:41.209058Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209116Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.209062Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=PDE timing_command=[TimeEntry { cmd: PDX, dist: 1, val: 6, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.208894Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.209136Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209113Z  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-09-01T11:28:41.209182Z  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-09-01T11:28:41.209193Z  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-09-01T11:28:41.209207Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209211Z  INFO ramu_rs::ddr4: timing_command level=Rank cmd=SRE timing_command=[TimeEntry { cmd: SRX, dist: 1, val: 7, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.209219Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209224Z  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-09-01T11:28:41.209230Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209238Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=ACT timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 0, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.209240Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209250Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209271Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209283Z  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-09-01T11:28:41.209294Z  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-09-01T11:28:41.209377Z  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-09-01T11:28:41.209402Z  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-09-01T11:28:41.209429Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209441Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209487Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209500Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209511Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209522Z  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-09-01T11:28:41.209537Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.209551Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209562Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.209577Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.209588Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.209602Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.209614Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209629Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209639Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209650Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209661Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209127Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209686Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209701Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209696Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209712Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209723Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209734Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209158Z  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-09-01T11:28:41.209745Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209755Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209159Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209773Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209768Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.209783Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209795Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209804Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209815Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209826Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209837Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209841Z  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-09-01T11:28:41.209850Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209861Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209859Z  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-09-01T11:28:41.209872Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209874Z  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-09-01T11:28:41.209883Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209780Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209956Z  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-09-01T11:28:41.209807Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.210043Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.210079Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.210095Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.210106Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210120Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210131Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210142Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210153Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210164Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210176Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210187Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210197Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210208Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210223Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210235Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210245Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210258Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210268Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210279Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210289Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210300Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210315Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210326Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210336Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210347Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210360Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210370Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210381Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210391Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210404Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210415Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210428Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210510Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-09-01T11:28:41.209888Z  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-09-01T11:28:41.210642Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210661Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210673Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209992Z  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-09-01T11:28:41.210721Z  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-09-01T11:28:41.210614Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2025-09-01T11:28:41.210797Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.210699Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210865Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.209927Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210891Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2025-09-01T11:28:41.210892Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210900Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210904Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.210942Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.210957Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.210993Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.211012Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.211025Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-09-01T11:28:41.211040Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2025-09-01T11:28:41.211056Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2025-09-01T11:28:41.211073Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2025-09-01T11:28:41.211087Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-09-01T11:28:41.211103Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2025-09-01T11:28:41.211117Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2025-09-01T11:28:41.211132Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2025-09-01T11:28:41.211145Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2025-09-01T11:28:41.211158Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2025-09-01T11:28:41.211172Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2025-09-01T11:28:41.211192Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.211205Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.211218Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.210740Z  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-09-01T11:28:41.211228Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.211237Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.211246Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.211257Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.211248Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211266Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.211270Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.210914Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211282Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211292Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211276Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.211303Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211315Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.211315Z  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-09-01T11:28:41.211325Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.211331Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.211335Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.211344Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211347Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.211354Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.211357Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.211369Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.211294Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211391Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.211367Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.211399Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.210911Z  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-09-01T11:28:41.211404Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.211409Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.211421Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.211413Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.211459Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.211419Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.211470Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.211480Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.211488Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.211465Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211497Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.211492Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.209252Z  INFO ramu_rs::ddr4: timing_command level=BankGroup cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211507Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.211499Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.211509Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211516Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.211517Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.211521Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211525Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.211528Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.211520Z  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-09-01T11:28:41.211532Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211538Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.211542Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PRE timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 16, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.211549Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211554Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211561Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211565Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RD timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 9, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.211481Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211574Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211578Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WR timing_command=[TimeEntry { cmd: PRE, dist: 1, val: 34, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.211583Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211585Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211590Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=RDA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 25, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.211594Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211597Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211602Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=WRA timing_command=[TimeEntry { cmd: ACT, dist: 1, val: 50, sibling: false }] [INFO] [stdout] 2025-09-01T11:28:41.211605Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-09-01T11:28:41.211609Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211614Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211621Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211694Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211624Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211740Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=1 [INFO] [stdout] 2025-09-01T11:28:41.211778Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 0] [INFO] [stdout] 2025-09-01T11:28:41.211536Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.211799Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 0 [INFO] [stdout] 2025-09-01T11:28:41.211559Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211816Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=65 [INFO] [stdout] 2025-09-01T11:28:41.211827Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211851Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.211833Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 1] [INFO] [stdout] 2025-09-01T11:28:41.211893Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 64 [INFO] [stdout] 2025-09-01T11:28:41.211931Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: addr=257 [INFO] [stdout] 2025-09-01T11:28:41.211951Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: [0, 0, 0, 0, 0, 4] [INFO] [stdout] 2025-09-01T11:28:41.211735Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211870Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211988Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211990Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212000Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212004Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212010Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212022Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212036Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212014Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212046Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212048Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212057Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212059Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.211969Z DEBUG testing ddr4 address: ramu_rs::ddr4::tests: 256 [INFO] [stdout] 2025-09-01T11:28:41.212085Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] test ddr4::tests::test_address ... ok [INFO] [stdout] 2025-09-01T11:28:41.212068Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212156Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212178Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212184Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212192Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212217Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212229Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212228Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212239Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212256Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212240Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212267Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212270Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212303Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212313Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212325Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212316Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212338Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212342Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212349Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212353Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212369Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212376Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-09-01T11:28:41.212381Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212391Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212402Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212413Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212427Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212438Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212464Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212476Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-09-01T11:28:41.212483Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212512Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212525Z  INFO ramu_rs::ddr4: timing_command level=Bank cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212539Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=ACT timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212553Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2025-09-01T11:28:41.212586Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.212641Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.212648Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.212621Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212653Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.212660Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=0 [INFO] [stdout] 2025-09-01T11:28:41.212661Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212664Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2025-09-01T11:28:41.212670Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.212674Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RD timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212680Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.212686Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WR timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212676Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.212692Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.212697Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=RDA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212699Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.212703Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.212708Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=WRA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212745Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212713Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.212710Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.212779Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=0 [INFO] [stdout] 2025-09-01T11:28:41.212795Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=39 [INFO] [stdout] 2025-09-01T11:28:41.212796Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.212809Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.212808Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=55 [INFO] [stdout] 2025-09-01T11:28:41.212821Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=1 [INFO] [stdout] 2025-09-01T11:28:41.212757Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212835Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=0 [INFO] [stdout] 2025-09-01T11:28:41.212863Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=16 [INFO] [stdout] 2025-09-01T11:28:41.212903Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=16 [INFO] [stdout] 2025-09-01T11:28:41.212817Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-09-01T11:28:41.212841Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.212948Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=16 [INFO] [stdout] 2025-09-01T11:28:41.212987Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2025-09-01T11:28:41.213103Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=16 [INFO] [stdout] 2025-09-01T11:28:41.213121Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=55 [INFO] [stdout] 2025-09-01T11:28:41.213125Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2025-09-01T11:28:41.213031Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.213136Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=39 [INFO] [stdout] 2025-09-01T11:28:41.213143Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2025-09-01T11:28:41.213152Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213151Z  INFO ramu_rs::ddr4: timing_command level=Row cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.213161Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213158Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-09-01T11:28:41.213167Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=ACT timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.213171Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213174Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2025-09-01T11:28:41.213201Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2025-09-01T11:28:41.213178Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.213214Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2025-09-01T11:28:41.213182Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213227Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2025-09-01T11:28:41.213228Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PREA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.213239Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213241Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RD timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.213240Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2025-09-01T11:28:41.213250Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213252Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WR timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.213254Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2025-09-01T11:28:41.213260Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213263Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=RDA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.213269Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213271Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213273Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=WRA timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.213278Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213281Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213284Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=REF timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.213288Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213292Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213296Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213295Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.213303Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.213306Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213308Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=PDX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.213312Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.213315Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213318Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRE timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.213322Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.213323Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213329Z  INFO ramu_rs::ddr4: timing_command level=Column cmd=SRX timing_command=[] [INFO] [stdout] 2025-09-01T11:28:41.213333Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213333Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213340Z  INFO ramu_rs::ddr4: read_latency read_latency=20 [INFO] [stdout] 2025-09-01T11:28:41.213342Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213345Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213354Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213375Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.213355Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213384Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.213387Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213394Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.213398Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213416Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213424Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213425Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213434Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213436Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213438Z DEBUG ramu_rs::test: addr_1=0 addr_2=8192 [INFO] [stdout] 2025-09-01T11:28:41.213462Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213466Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.213470Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213471Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213476Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.213479Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.213480Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213485Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.213490Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213490Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=1 [INFO] [stdout] 2025-09-01T11:28:41.213495Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213497Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213499Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.213504Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213510Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.213513Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213521Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.213512Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213571Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.213585Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213590Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213599Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213596Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-09-01T11:28:41.213609Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213610Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=0 future=40 [INFO] [stdout] 2025-09-01T11:28:41.213618Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213626Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213623Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=0 future=56 [INFO] [stdout] 2025-09-01T11:28:41.213635Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213636Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=0 future=2 [INFO] [stdout] 2025-09-01T11:28:41.213644Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213652Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213649Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=0 future=1 [INFO] [stdout] 2025-09-01T11:28:41.213661Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213663Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=0 future=17 [INFO] [stdout] 2025-09-01T11:28:41.213671Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213678Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213677Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=0 future=17 [INFO] [stdout] 2025-09-01T11:28:41.213687Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213690Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=0 future=17 [INFO] [stdout] 2025-09-01T11:28:41.213697Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213703Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=0 future=17 [INFO] [stdout] 2025-09-01T11:28:41.213707Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213717Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213716Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=0 future=56 [INFO] [stdout] 2025-09-01T11:28:41.213726Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213729Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=0 future=40 [INFO] [stdout] 2025-09-01T11:28:41.213733Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213744Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213743Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213753Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213752Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213761Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213769Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213770Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213779Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213780Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=16 [INFO] [stdout] 2025-09-01T11:28:41.213787Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.213789Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.213796Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.213800Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.213805Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213811Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.213813Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213822Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213821Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.213831Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213834Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=20 [INFO] [stdout] 2025-09-01T11:28:41.213839Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.213847Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.213847Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=20 [INFO] [stdout] 2025-09-01T11:28:41.213856Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213860Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=20 [INFO] [stdout] 2025-09-01T11:28:41.213864Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213873Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213873Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=20 [INFO] [stdout] 2025-09-01T11:28:41.213882Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213886Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=26 [INFO] [stdout] 2025-09-01T11:28:41.213890Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.213899Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.213898Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=26 [INFO] [stdout] 2025-09-01T11:28:41.213908Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213911Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=39 future=25 [INFO] [stdout] 2025-09-01T11:28:41.213916Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213924Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213924Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=1 future=37 [INFO] [stdout] 2025-09-01T11:28:41.213933Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213937Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=22 [INFO] [stdout] 2025-09-01T11:28:41.213941Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.213951Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.213951Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=22 [INFO] [stdout] 2025-09-01T11:28:41.213960Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213964Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=39 future=25 [INFO] [stdout] 2025-09-01T11:28:41.213968Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.213977Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.213987Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.213983Z 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-09-01T11:28:41.213995Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214004Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214014Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214022Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214031Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214040Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214047Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214056Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214066Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214074Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214083Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214093Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214100Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214108Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214118Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214125Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214136Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214145Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214153Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214161Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214171Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214179Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214188Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214197Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214204Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214213Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214222Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214230Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214239Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214249Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214257Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214266Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.213532Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.214276Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214281Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214285Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214304Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214311Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214315Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214322Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214323Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214329Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214332Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214354Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214372Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.214381Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214381Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214401Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214408Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214412Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214419Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214421Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214427Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214429Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214436Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214438Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214478Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.214480Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214487Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214488Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214497Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214497Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214507Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214513Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214515Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214521Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214524Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214530Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214534Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214539Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.214542Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214547Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214551Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214556Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214560Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214566Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214568Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214574Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214577Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214583Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214586Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214593Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.214594Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214600Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214604Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214610Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214614Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214619Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214622Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214627Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214631Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214636Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214641Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214645Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.214649Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214653Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214657Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214662Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214668Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17 [INFO] [stdout] 2025-09-01T11:28:41.214672Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214677Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.214680Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214688Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214688Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.214697Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.214698Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.214705Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214708Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.214714Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214724Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214720Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2025-09-01T11:28:41.214734Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2025-09-01T11:28:41.214731Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214756Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214766Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.214762Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2025-09-01T11:28:41.214774Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214775Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2025-09-01T11:28:41.214783Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214793Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214788Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27 [INFO] [stdout] 2025-09-01T11:28:41.214800Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214801Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27 [INFO] [stdout] 2025-09-01T11:28:41.214809Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214818Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.214814Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26 [INFO] [stdout] 2025-09-01T11:28:41.214826Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214827Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38 [INFO] [stdout] 2025-09-01T11:28:41.214834Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214844Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214840Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23 [INFO] [stdout] 2025-09-01T11:28:41.214852Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214853Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23 [INFO] [stdout] 2025-09-01T11:28:41.214861Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214871Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.214866Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26 [INFO] [stdout] 2025-09-01T11:28:41.214879Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214882Z 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-09-01T11:28:41.214888Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214896Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214898Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214904Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214905Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214913Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214914Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214923Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.214923Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214931Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214932Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.214940Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214941Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.214949Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214950Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.214957Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.214985Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.214998Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215014Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215024Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215039Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.215048Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.215059Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.215071Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=17 [INFO] [stdout] 2025-09-01T11:28:41.215083Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.215094Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.215107Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.215118Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.214958Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215163Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2025-09-01T11:28:41.215177Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215179Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2025-09-01T11:28:41.215190Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.215192Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=0 future=21 [INFO] [stdout] 2025-09-01T11:28:41.215198Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215205Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=0 future=21 [INFO] [stdout] 2025-09-01T11:28:41.215218Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=0 future=27 [INFO] [stdout] 2025-09-01T11:28:41.215232Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=0 future=27 [INFO] [stdout] 2025-09-01T11:28:41.215248Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=40 future=26 [INFO] [stdout] 2025-09-01T11:28:41.215261Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=2 future=38 [INFO] [stdout] 2025-09-01T11:28:41.215274Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=0 future=23 [INFO] [stdout] 2025-09-01T11:28:41.215325Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=0 future=23 [INFO] [stdout] 2025-09-01T11:28:41.215207Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.211888Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215407Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=40 future=26 [INFO] [stdout] 2025-09-01T11:28:41.215422Z 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-09-01T11:28:41.215422Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215436Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215439Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.215476Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.215495Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215444Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215505Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215512Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215515Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215525Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215527Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215533Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215536Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.215542Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215545Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.215551Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215555Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215559Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215564Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215568Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215573Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215578Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215585Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215586Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215593Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.215604Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215616Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.215617Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215626Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215627Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215634Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215636Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215642Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215646Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215652Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215654Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215660Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.215663Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215669Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.215673Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215679Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215680Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215687Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215689Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215695Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215699Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215705Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215707Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215712Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.215716Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215721Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.215726Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215731Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215735Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215738Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215744Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215747Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215753Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215757Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215761Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215770Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215764Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.215780Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215781Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.215788Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215790Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215797Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215798Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215807Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215807Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215814Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215817Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215823Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215824Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.215833Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215833Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.215842Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215840Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215849Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215850Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215857Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215861Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215867Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215868Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215874Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.215877Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215883Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.215887Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215893Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215895Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215900Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215904Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215909Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215914Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215919Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215922Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215927Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.215931Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215935Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.215941Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215945Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215948Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215952Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215957Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215961Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215967Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215971Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215975Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.215979Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.215985Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215988Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.215994Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.215997Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216002Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216005Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216012Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216014Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216022Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216023Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216030Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216031Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=0 [INFO] [stdout] 2025-09-01T11:28:41.216039Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216040Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.216051Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=17 [INFO] [stdout] 2025-09-01T11:28:41.216056Z 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-09-01T11:28:41.216061Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.216066Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216071Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.216073Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216083Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216082Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.216093Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216094Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.216101Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216106Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=21 [INFO] [stdout] 2025-09-01T11:28:41.216112Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216121Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216119Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=21 [INFO] [stdout] 2025-09-01T11:28:41.216129Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216131Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=0 future=21 [INFO] [stdout] 2025-09-01T11:28:41.216138Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216142Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=0 future=21 [INFO] [stdout] 2025-09-01T11:28:41.216149Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40 [INFO] [stdout] 2025-09-01T11:28:41.216153Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=0 future=36 [INFO] [stdout] 2025-09-01T11:28:41.216158Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.216165Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=0 future=36 [INFO] [stdout] 2025-09-01T11:28:41.216168Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.216179Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.216179Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=40 future=51 [INFO] [stdout] 2025-09-01T11:28:41.216190Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-09-01T11:28:41.216192Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=2 future=51 [INFO] [stdout] 2025-09-01T11:28:41.216202Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56 [INFO] [stdout] 2025-09-01T11:28:41.216206Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=23 [INFO] [stdout] 2025-09-01T11:28:41.216215Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56 [INFO] [stdout] 2025-09-01T11:28:41.216219Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=23 [INFO] [stdout] 2025-09-01T11:28:41.216229Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56 [INFO] [stdout] 2025-09-01T11:28:41.216232Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=0 future=42 [INFO] [stdout] 2025-09-01T11:28:41.216243Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216245Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=0 future=42 [INFO] [stdout] 2025-09-01T11:28:41.216251Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.216261Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216259Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=40 future=51 [INFO] [stdout] 2025-09-01T11:28:41.216269Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.216278Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216280Z 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-09-01T11:28:41.216286Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.216295Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216295Z 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-09-01T11:28:41.216303Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.216305Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216312Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216314Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216320Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.216324Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216329Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216334Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216337Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.216342Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216348Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216351Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216357Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.216361Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216366Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216368Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216374Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.216377Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216384Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216387Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216392Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.216395Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216401Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216404Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216409Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.216413Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216418Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216421Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216426Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.216430Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216435Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216443Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.216440Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216470Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216472Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216478Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.216482Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216488Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216496Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216496Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.216504Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216506Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216514Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216519Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.216524Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216528Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216533Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216536Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.216543Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216546Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56 [INFO] [stdout] 2025-09-01T11:28:41.216552Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216554Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.216561Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216564Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.216570Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216575Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.216580Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216585Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-09-01T11:28:41.216588Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216596Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216597Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216607Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216604Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2025-09-01T11:28:41.216615Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216618Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95 [INFO] [stdout] 2025-09-01T11:28:41.216625Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216635Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216631Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111 [INFO] [stdout] 2025-09-01T11:28:41.216642Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216644Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57 [INFO] [stdout] 2025-09-01T11:28:41.216652Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216658Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2025-09-01T11:28:41.216663Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216672Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216671Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72 [INFO] [stdout] 2025-09-01T11:28:41.216682Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216683Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72 [INFO] [stdout] 2025-09-01T11:28:41.216693Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216696Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72 [INFO] [stdout] 2025-09-01T11:28:41.216701Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216711Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216708Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72 [INFO] [stdout] 2025-09-01T11:28:41.216721Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216722Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111 [INFO] [stdout] 2025-09-01T11:28:41.216729Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216735Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95 [INFO] [stdout] 2025-09-01T11:28:41.216738Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216749Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216749Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216757Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216766Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.215393Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.216783Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216790Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216792Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216800Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216801Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216810Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.216811Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216818Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216820Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216827Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216829Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216837Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.216839Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216847Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216857Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216867Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216845Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216875Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216879Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216884Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216892Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.216895Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216900Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216903Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216909Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216912Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216919Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.216922Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216926Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216931Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216941Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216951Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216935Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216959Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216969Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.216969Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216977Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216980Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.216986Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.216989Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.216996Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.216999Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217004Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217009Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.217013Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217018Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217028Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217040Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.217022Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.217048Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217052Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217058Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217061Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217067Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.217071Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.217076Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217079Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217085Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217088Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217095Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.217098Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.217103Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217113Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217123Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.217105Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217131Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217135Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217140Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217145Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.217150Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.217153Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217158Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217162Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217167Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217172Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.217176Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.217181Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217185Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217195Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217205Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.217190Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217213Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217222Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.217222Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217230Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217233Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.217239Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217241Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217249Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.217250Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217257Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217261Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.217265Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217269Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217279Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217290Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=51 [INFO] [stdout] 2025-09-01T11:28:41.217275Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.217299Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.217304Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217311Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.217314Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217325Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.217323Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.217335Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217336Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-09-01T11:28:41.217344Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217349Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=67 [INFO] [stdout] 2025-09-01T11:28:41.217363Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=67 [INFO] [stdout] 2025-09-01T11:28:41.217359Z 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-09-01T11:28:41.217378Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=67 [INFO] [stdout] 2025-09-01T11:28:41.217391Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.217393Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.217399Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217401Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.217408Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217410Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.217418Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.217419Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.217426Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217430Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.217434Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217444Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.217482Z DEBUG ramu_rs::ddr4: the row is open row_id=0 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.217491Z DEBUG ramu_rs::dram: find pre command level=Bank command=PRE [INFO] [stdout] 2025-09-01T11:28:41.217501Z DEBUG ramu_rs::controller: issue cmd cmd=PRE clk=40 [INFO] [stdout] 2025-09-01T11:28:41.217516Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.217530Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.217564Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.217575Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-09-01T11:28:41.217587Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=REF current=56 future=56 [INFO] [stdout] 2025-09-01T11:28:41.217619Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=PRE timing.cmd=SRE current=0 future=56 [INFO] [stdout] 2025-09-01T11:28:41.217691Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=PRE timing.cmd=ACT current=56 future=56 [INFO] [stdout] 2025-09-01T11:28:41.217785Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.217801Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.217813Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.217821Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.217832Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.217902Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.217970Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.218014Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.218063Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stderr] error: test failed, to rerun pass `--lib` [INFO] [stdout] 2025-09-01T11:28:41.218106Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.218172Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.218187Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.218198Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.218210Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.218254Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.218277Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.218290Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.218299Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.218333Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.218345Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.218357Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.218369Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.218379Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.218390Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.218423Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.218433Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.218443Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.218476Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.218488Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.218497Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.218518Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.218570Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.218647Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=56 [INFO] [stdout] 2025-09-01T11:28:41.218663Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.218675Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.218686Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.218697Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-09-01T11:28:41.216758Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.218746Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.218797Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.218813Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.218823Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.218834Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.218842Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.218852Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.218864Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.218872Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.218886Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.218897Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.218905Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.218915Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.218925Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.218933Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.218943Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.218953Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.218967Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.218977Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.218993Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.219002Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.219011Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.219021Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.219029Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.219041Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.219051Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.219063Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.219072Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.219086Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.219095Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.219104Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.219114Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.219123Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.219132Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.219142Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.219152Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.219162Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.219176Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.219184Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.219193Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.219204Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.219212Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.219222Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.219232Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.219240Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.219250Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.219260Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=72 [INFO] [stdout] 2025-09-01T11:28:41.219278Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.219290Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.219301Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.219315Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-09-01T11:28:41.219328Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=0 future=76 [INFO] [stdout] 2025-09-01T11:28:41.219342Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=0 future=76 [INFO] [stdout] 2025-09-01T11:28:41.219356Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=27 future=76 [INFO] [stdout] 2025-09-01T11:28:41.219370Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=27 future=76 [INFO] [stdout] 2025-09-01T11:28:41.219386Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=21 future=91 [INFO] [stdout] 2025-09-01T11:28:41.219399Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=21 future=91 [INFO] [stdout] 2025-09-01T11:28:41.219412Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=95 future=106 [INFO] [stdout] 2025-09-01T11:28:41.219468Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.219523Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2025-09-01T11:28:41.219554Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=40 future=95 [INFO] [stdout] 2025-09-01T11:28:41.219581Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=56 future=111 [INFO] [stdout] 2025-09-01T11:28:41.219615Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=38 future=57 [INFO] [stdout] 2025-09-01T11:28:41.219642Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=56 [INFO] [stdout] 2025-09-01T11:28:41.219695Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=72 [INFO] [stdout] 2025-09-01T11:28:41.219728Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=72 [INFO] [stdout] 2025-09-01T11:28:41.219792Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=72 [INFO] [stdout] 2025-09-01T11:28:41.219825Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=72 [INFO] [stdout] 2025-09-01T11:28:41.219879Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=56 future=111 [INFO] [stdout] 2025-09-01T11:28:41.219908Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=40 future=95 [INFO] [stdout] 2025-09-01T11:28:41.219963Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.219997Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.220034Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.220062Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.220103Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.220133Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.220166Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.220190Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.220209Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.220333Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.220374Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.220428Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.220518Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.220554Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.220832Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.220916Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.220926Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.220936Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.220887Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=57 future=106 [INFO] [stdout] 2025-09-01T11:28:41.221116Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=0 future=78 [INFO] [stdout] 2025-09-01T11:28:41.221137Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=0 future=78 [INFO] [stdout] 2025-09-01T11:28:41.221234Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.221281Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.221293Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.221304Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.221311Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.221320Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.221329Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.221336Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.221344Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.221353Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.221361Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.221368Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.221375Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.221380Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.221385Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.221391Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.221396Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.221402Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.221408Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.221413Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.221419Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.221426Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.221431Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.221438Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.221160Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=23 future=97 [INFO] [stdout] 2025-09-01T11:28:41.221595Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=23 future=97 [INFO] [stdout] 2025-09-01T11:28:41.221634Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=95 future=106 [INFO] [stdout] 2025-09-01T11:28:41.221694Z 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-09-01T11:28:41.221762Z 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-09-01T11:28:41.221980Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.222008Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.222019Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.222031Z DEBUG ramu_rs::controller: the init cmd frist_cmd=RD [INFO] [stdout] 2025-09-01T11:28:41.222039Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.222051Z DEBUG ramu_rs::dram: find pre command level=Bank command=RD [INFO] [stdout] 2025-09-01T11:28:41.222062Z DEBUG ramu_rs::controller: issue cmd cmd=RD clk=72 [INFO] [stdout] test test::test_memory_read_and_write ... ok [INFO] [stdout] 2025-09-01T11:28:41.222077Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.222302Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.222354Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.222385Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-09-01T11:28:41.222470Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RD current=21 future=76 [INFO] [stdout] 2025-09-01T11:28:41.222517Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=RD timing.cmd=RDA current=21 future=76 [INFO] [stdout] 2025-09-01T11:28:41.222541Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RD current=21 future=76 [INFO] [stdout] 2025-09-01T11:28:41.222555Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=RDA current=21 future=76 [INFO] [stdout] 2025-09-01T11:28:41.222569Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WR current=27 future=82 [INFO] [stdout] 2025-09-01T11:28:41.222582Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=WRA current=27 future=82 [INFO] [stdout] 2025-09-01T11:28:41.222595Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PREA current=95 future=81 [INFO] [stdout] 2025-09-01T11:28:41.222608Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=RD timing.cmd=PDE current=57 future=93 [INFO] [stdout] 2025-09-01T11:28:41.222623Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RD current=23 future=78 [INFO] [stdout] 2025-09-01T11:28:41.222636Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=RD timing.cmd=RDA current=23 future=78 [INFO] [stdout] 2025-09-01T11:28:41.222650Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=RD timing.cmd=PRE current=95 future=81 [INFO] [stdout] 2025-09-01T11:28:41.222665Z 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-09-01T11:28:41.222684Z DEBUG ramu_rs::test: recv req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Read, arrival_time: 0, finish_time: 92 } [INFO] [stdout] test test::test_memory_diffrent_row ... ok [INFO] [stdout] 2025-09-01T11:28:41.217438Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.224612Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.224638Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.224659Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.224669Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.224682Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.224691Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.224703Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.224713Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.224780Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.224837Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.224879Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.224917Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.224963Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.224994Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.225024Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.225061Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.225099Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.225146Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.225185Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.225222Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.225286Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.225325Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.225371Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.225408Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.225466Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.225527Z DEBUG ramu_rs::dram: find pre command level=Bank command=ACT [INFO] [stdout] 2025-09-01T11:28:41.225569Z DEBUG ramu_rs::controller: issue cmd cmd=ACT clk=67 [INFO] [stdout] 2025-09-01T11:28:41.225642Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.225677Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.225724Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.225793Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-09-01T11:28:41.225835Z DEBUG ramu_rs::ddr4: ACT in Bank child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.225870Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=ACT current=1 future=67 [INFO] [stdout] 2025-09-01T11:28:41.225953Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PREA current=51 future=106 [INFO] [stdout] 2025-09-01T11:28:41.225997Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=REF current=67 future=122 [INFO] [stdout] 2025-09-01T11:28:41.226073Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=ACT timing.cmd=PDE current=51 future=68 [INFO] [stdout] 2025-09-01T11:28:41.226122Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=ACT timing.cmd=ACT current=1 future=67 [INFO] [stdout] 2025-09-01T11:28:41.226211Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RD current=17 future=83 [INFO] [stdout] 2025-09-01T11:28:41.226251Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=RDA current=17 future=83 [INFO] [stdout] 2025-09-01T11:28:41.226323Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WR current=17 future=83 [INFO] [stdout] 2025-09-01T11:28:41.226363Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=WRA current=17 future=83 [INFO] [stdout] 2025-09-01T11:28:41.226404Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=ACT current=67 future=122 [INFO] [stdout] 2025-09-01T11:28:41.226420Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=ACT timing.cmd=PRE current=51 future=106 [INFO] [stdout] 2025-09-01T11:28:41.226439Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.226464Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.226475Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.226485Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.226494Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.226504Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.226513Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.226522Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.226531Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.226542Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.226550Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.226560Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.226570Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.226578Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.226588Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.226599Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.226607Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.226617Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.226627Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.226635Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.226644Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.226654Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.226663Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.226672Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.226686Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.226695Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.226705Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.226716Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.226725Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.226735Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.226746Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.226755Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.226765Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.226786Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.226796Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.226805Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.226816Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.226825Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.226835Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.226846Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.226855Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.226864Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.226875Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.226884Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.226894Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.226905Z DEBUG ramu_rs::controller: the init cmd frist_cmd=WR [INFO] [stdout] 2025-09-01T11:28:41.226913Z DEBUG ramu_rs::ddr4: the row is open row_id=1 child_id=1 [INFO] [stdout] 2025-09-01T11:28:41.226923Z DEBUG ramu_rs::dram: find pre command level=Bank command=WR [INFO] [stdout] 2025-09-01T11:28:41.226934Z DEBUG ramu_rs::controller: issue cmd cmd=WR clk=83 [INFO] [stdout] 2025-09-01T11:28:41.226944Z DEBUG ramu_rs::dram: trying to update state level=Channel child_level=Rank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.226955Z DEBUG ramu_rs::dram: trying to update state level=Rank child_level=BankGroup child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.226969Z DEBUG ramu_rs::dram: trying to update state level=BankGroup child_level=Bank child_index=0 [INFO] [stdout] 2025-09-01T11:28:41.226980Z DEBUG ramu_rs::dram: trying to update state level=Bank child_level=Row child_index=1 [INFO] [stdout] 2025-09-01T11:28:41.226993Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WR current=21 future=87 [INFO] [stdout] 2025-09-01T11:28:41.227006Z DEBUG ramu_rs::dram: update timing self.level=Channel cmd=WR timing.cmd=WRA current=21 future=87 [INFO] [stdout] 2025-09-01T11:28:41.227021Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WR current=21 future=87 [INFO] [stdout] 2025-09-01T11:28:41.227036Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=WRA current=21 future=87 [INFO] [stdout] 2025-09-01T11:28:41.227050Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RD current=36 future=102 [INFO] [stdout] 2025-09-01T11:28:41.227064Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=RDA current=36 future=102 [INFO] [stdout] 2025-09-01T11:28:41.227077Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PREA current=106 future=117 [INFO] [stdout] 2025-09-01T11:28:41.227092Z DEBUG ramu_rs::dram: update timing self.level=Rank cmd=WR timing.cmd=PDE current=68 future=117 [INFO] [stdout] 2025-09-01T11:28:41.227107Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WR current=23 future=89 [INFO] [stdout] 2025-09-01T11:28:41.227122Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=WRA current=23 future=89 [INFO] [stdout] 2025-09-01T11:28:41.227136Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RD current=42 future=108 [INFO] [stdout] 2025-09-01T11:28:41.227150Z DEBUG ramu_rs::dram: update timing self.level=BankGroup cmd=WR timing.cmd=RDA current=42 future=108 [INFO] [stdout] 2025-09-01T11:28:41.227187Z DEBUG ramu_rs::dram: update timing self.level=Bank cmd=WR timing.cmd=PRE current=106 future=117 [INFO] [stdout] 2025-09-01T11:28:41.227204Z 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-09-01T11:28:41.227218Z DEBUG ramu_rs::test: recv req=Request { addr: 8192, addr_vec: [0, 0, 0, 0, 1, 0], done_setup: true, req_type: Write, arrival_time: 0, finish_time: 83 } [INFO] [stdout] test test::test_memory_write ... ok [INFO] [stdout] test controller::tests::test_controller_simple_read ... FAILED [INFO] [stdout] [INFO] [stdout] failures: [INFO] [stdout] [INFO] [stdout] ---- controller::tests::test_controller_simple_read stdout ---- [INFO] [stdout] [INFO] [stdout] thread 'controller::tests::test_controller_simple_read' (25) panicked at src/controller.rs:300:9: [INFO] [stdout] assertion failed: controller.finished_queue.is_empty() [INFO] [stdout] stack backtrace: [INFO] [stdout] 0: 0x5a1dc2293032 - std::backtrace_rs::backtrace::libunwind::trace::h7cddb8376417e7cc [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/../../backtrace/src/backtrace/libunwind.rs:117:9 [INFO] [stdout] 1: 0x5a1dc2293032 - std::backtrace_rs::backtrace::trace_unsynchronized::hb4e41acf4b349ff1 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/../../backtrace/src/backtrace/mod.rs:66:14 [INFO] [stdout] 2: 0x5a1dc2293032 - std::sys::backtrace::_print_fmt::h1222b80910ba6eb5 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/sys/backtrace.rs:66:9 [INFO] [stdout] 3: 0x5a1dc2293032 - ::fmt::h5bb8a979ba5db788 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/sys/backtrace.rs:39:26 [INFO] [stdout] 4: 0x5a1dc22a43ef - core::fmt::rt::Argument::fmt::h2ee2c138a50a7796 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/core/src/fmt/rt.rs:173:76 [INFO] [stdout] 5: 0x5a1dc22a43ef - core::fmt::write::h1e0dbf07fe3990bd [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/core/src/fmt/mod.rs:1468:25 [INFO] [stdout] 6: 0x5a1dc2260743 - std::io::default_write_fmt::h7d7ad5ed6a883d81 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/io/mod.rs:639:11 [INFO] [stdout] 7: 0x5a1dc2260743 - std::io::Write::write_fmt::hc477d9325b345ece [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/io/mod.rs:1954:13 [INFO] [stdout] 8: 0x5a1dc226c502 - std::sys::backtrace::BacktraceLock::print::h788d486777205086 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/sys/backtrace.rs:42:9 [INFO] [stdout] 9: 0x5a1dc22710af - std::panicking::default_hook::{{closure}}::ha7bdfeb5949fc0fa [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/panicking.rs:301:27 [INFO] [stdout] 10: 0x5a1dc2270f41 - std::panicking::default_hook::h6dad75ec721846f4 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/panicking.rs:325:9 [INFO] [stdout] 11: 0x5a1dc208294e - as core::ops::function::Fn>::call::h33799d04b0b96146 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/alloc/src/boxed.rs:1999:9 [INFO] [stdout] 12: 0x5a1dc208294e - test::test_main_with_exit_callback::{{closure}}::h880e31c829a2eb5d [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/test/src/lib.rs:145:21 [INFO] [stdout] 13: 0x5a1dc227174e - as core::ops::function::Fn>::call::h5e1b8c652ea49180 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/alloc/src/boxed.rs:1999:9 [INFO] [stdout] 14: 0x5a1dc227174e - std::panicking::panic_with_hook::hba00e869ada17676 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/panicking.rs:842:13 [INFO] [stdout] 15: 0x5a1dc22714e6 - std::panicking::panic_handler::{{closure}}::h3d21149c258e5ceb [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/panicking.rs:700:13 [INFO] [stdout] 16: 0x5a1dc226c639 - std::sys::backtrace::__rust_end_short_backtrace::h4f5d9b9dfb3e6ec1 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/sys/backtrace.rs:174:18 [INFO] [stdout] 17: 0x5a1dc22549ad - __rustc[9a7a9f9af7564de1]::rust_begin_unwind [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/panicking.rs:698:5 [INFO] [stdout] 18: 0x5a1dc22adb60 - core::panicking::panic_fmt::h78e817a90331d98b [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/core/src/panicking.rs:75:14 [INFO] [stdout] 19: 0x5a1dc22adb3c - core::panicking::panic::h33d2d00634ffed6f [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/core/src/panicking.rs:145:5 [INFO] [stdout] 20: 0x5a1dc204a4ef - ramu_rs::controller::tests::test_controller_simple_read::he2f4ed7121a8a734 [INFO] [stdout] at /opt/rustwide/workdir/src/controller.rs:300:9 [INFO] [stdout] 21: 0x5a1dc204a5f7 - ramu_rs::controller::tests::test_controller_simple_read::{{closure}}::h453965d018636e20 [INFO] [stdout] at /opt/rustwide/workdir/src/controller.rs:277:37 [INFO] [stdout] 22: 0x5a1dc2051806 - core::ops::function::FnOnce::call_once::h500ca54a58325d56 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/core/src/ops/function.rs:253:5 [INFO] [stdout] 23: 0x5a1dc208274b - core::ops::function::FnOnce::call_once::h7f4b4fba903e39d5 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/core/src/ops/function.rs:253:5 [INFO] [stdout] 24: 0x5a1dc208274b - test::__rust_begin_short_backtrace::h9277cb6a2ccfc000 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/test/src/lib.rs:663:18 [INFO] [stdout] 25: 0x5a1dc20981f5 - test::run_test_in_process::{{closure}}::h9aea5ca90d1f4423 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/test/src/lib.rs:686:74 [INFO] [stdout] 26: 0x5a1dc20981f5 - as core::ops::function::FnOnce<()>>::call_once::h364f5fe6cc8afa85 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/core/src/panic/unwind_safe.rs:272:9 [INFO] [stdout] 27: 0x5a1dc20981f5 - std::panicking::catch_unwind::do_call::h2b2bec3317fe53ec [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/panicking.rs:590:40 [INFO] [stdout] 28: 0x5a1dc20981f5 - std::panicking::catch_unwind::hc3763734156da4af [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/panicking.rs:553:19 [INFO] [stdout] 29: 0x5a1dc20981f5 - std::panic::catch_unwind::h28038391e867eabc [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/panic.rs:359:14 [INFO] [stdout] 30: 0x5a1dc20981f5 - test::run_test_in_process::had0273166695a036 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/test/src/lib.rs:686:27 [INFO] [stdout] 31: 0x5a1dc20981f5 - test::run_test::{{closure}}::h743d09d4bb476605 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/test/src/lib.rs:607:43 [INFO] [stdout] 32: 0x5a1dc206ec14 - test::run_test::{{closure}}::he950b8f9118d37e2 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/test/src/lib.rs:637:41 [INFO] [stdout] 33: 0x5a1dc206ec14 - std::sys::backtrace::__rust_begin_short_backtrace::hbfaffa6539f6abb7 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/sys/backtrace.rs:158:18 [INFO] [stdout] 34: 0x5a1dc20724fa - std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}::hcce3c2c65b9c3b20 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/thread/mod.rs:559:17 [INFO] [stdout] 35: 0x5a1dc20724fa - as core::ops::function::FnOnce<()>>::call_once::hb66b30b6d37985a5 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/core/src/panic/unwind_safe.rs:272:9 [INFO] [stdout] 36: 0x5a1dc20724fa - std::panicking::catch_unwind::do_call::h992bbe2c32dc1d79 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/panicking.rs:590:40 [INFO] [stdout] 37: 0x5a1dc20724fa - std::panicking::catch_unwind::h412991d5237de610 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/panicking.rs:553:19 [INFO] [stdout] 38: 0x5a1dc20724fa - std::panic::catch_unwind::ha82b139b3eb5840a [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/panic.rs:359:14 [INFO] [stdout] 39: 0x5a1dc20724fa - std::thread::Builder::spawn_unchecked_::{{closure}}::ha823b36f5114938e [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/thread/mod.rs:557:30 [INFO] [stdout] 40: 0x5a1dc20724fa - core::ops::function::FnOnce::call_once{{vtable.shim}}::hf120e7b1db22ac07 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/core/src/ops/function.rs:253:5 [INFO] [stdout] 41: 0x5a1dc22668bf - as core::ops::function::FnOnce>::call_once::h3e049222c99298ac [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/alloc/src/boxed.rs:1985:9 [INFO] [stdout] 42: 0x5a1dc22668bf - std::sys::pal::unix::thread::Thread::new::thread_start::h942e336943ad5963 [INFO] [stdout] at /rustc/cdb45c87e2cd43495379f7e867e3cc15dcee9f93/library/std/src/sys/pal/unix/thread.rs:118:17 [INFO] [stdout] 43: 0x7bfde9fd6aa4 - [INFO] [stdout] 44: 0x7bfdea063a34 - clone [INFO] [stdout] 45: 0x0 - [INFO] [stdout] [INFO] [stdout] [INFO] [stdout] failures: [INFO] [stdout] controller::tests::test_controller_simple_read [INFO] [stdout] [INFO] [stdout] test result: FAILED. 6 passed; 1 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.04s [INFO] [stdout] [INFO] running `Command { std: "docker" "inspect" "18584cf976070e6815fcd360f467e7ab0360ce11739c201e2b1c8d90ef1a655d", kill_on_drop: false }` [INFO] running `Command { std: "docker" "rm" "-f" "18584cf976070e6815fcd360f467e7ab0360ce11739c201e2b1c8d90ef1a655d", kill_on_drop: false }` [INFO] [stdout] 18584cf976070e6815fcd360f467e7ab0360ce11739c201e2b1c8d90ef1a655d